St2: Listing actions on CLI in YAML or JSON takes a long time
Problem
Came across a performance problem today when listing actions in the AWS pack using YAML and JSON formatting options. Below are command outputs (truncated) that show the timings for the various formatting options and their differences.
Standard Formatting
$ time st2 action list -p aws | tail -n 1
+-----------------------------------------+------+-----------------------------------------+
real 0m11.901s
user 0m1.186s
sys 0m0.079s
YAML Formatting
$ time st2 action list -p aws -y | tail -n 1
real 1m46.834s
user 1m34.807s
sys 0m1.106s
JSON Formatting
time st2 action list -p aws -j | tail -n1
]
real 1m46.032s
user 1m34.095s
sys 0m1.140s
Observations
When running both the YAML and JSON formatting options the st2 command was using 100% CPU in top. Memory was stable at around 68M throughout the processing.
nmaludy
All 11 comments
Just a note, similar to https://github.com/StackStorm/st2/issues/3692 and https://github.com/StackStorm/st2/issues/3686 issues, I think that StackStorm _should_ be able to handle thousands of actions in pack(s) by design without a problem.
It's not the AWS pack guilty, but the root cause has to be fixed: we just need to identify the bottlenecks and optimize the entire StackStorm performance when dealing with bigger packs (which wasn't really a big focus before).
armab
on 23 Aug 2017
Perfect. Yeah, i think this is another optimization opportunity on the st2client side. The gunicorn process spiked for about 10s then the rest of the time was spent in the st2 process (st2client).
nmaludy
on 23 Aug 2017
Thanks for reporting this.
First we need to clarify, as you correctly determined it, that slowdown is due to parsing and mangling of JSON / YAML inside the CLI / client. API returns response in a reasonable time frame:
time curl "http://127.0.0.1:9101/v1/actions?pack=aws" > /dev/null
real 0m9.704s
user 0m0.009s
sys 0m0.005s
Now the question is how to solve that. For one, I don't think you ever want to non-programatically (e.g. when using CLI) see more than some reasonable number of items by default (e.g. 50 / 100 by once, similar limit as we use for other CLI commands).
I would propose to implement default limit for action list (100) and allowing user to filter / drill down and paginate through the pages, if needed.
So in short, I think that the best solution for CLI and WebUI is to implement pagination for actions API endpoint.
/cc @enykeev - what do you think about WebUI implementation? I think pagination is a very reasonable thing to do (as long as we don't do some infinite load stuff / magic page loading which makes for a horrible UX).
Kami
on 1 Sep 2017
@Kami while I agree that it is time for us to switch to some sort of pagination for actions (and likely rules and packs too), the general problem of integrating it into st2web is the lack of reverse mechanics, i.e. loading a page with particular action on it.
At the moment, user is able to hotlink the action with URL like http://localhost:3000/#/actions/bitbucket.list_services/code which is pretty useful, but relies on the fact that all actions are already listed on the left side. As soon as we start using naive pagination, we won't be able to highlight the action on the left side unless it's on the first page. We have similar problem in executions, but we decided that in this particular case we can live with neighboring objects being less discoverable.
The reasonable middle ground will be to load one pack at a time so instead of looking for a page for an action, we would only need its pack name which we already have. Problem with that approach, though, is outlined in this issue's description - loading even a single pack may take unacceptably long time.
enykeev
on 4 Sep 2017
For one, I don't think you ever want to non-programatically (e.g. when using CLI) see more than some reasonable number of items by default (e.g. 50 / 100 by once, similar limit as we use for other CLI commands).
Sadly, I can't agree here and noted the same before https://github.com/StackStorm/st2/issues/3708#issuecomment-326986207.
As ops people, we want to get all the results and then process | grep | pipe, do anything with data in most of the cases. Pagination is so confusing when you work with CLI on a prod server. Filtering output via st2 CLI itself helps, but not all the time.
Forcing pagination here would be another way to hide the problem under the rug.
If json parsing is slow, can we investigate something like cjson or ujson, ijson instead and approaches like that?
Example for cjson:
https://pypi.python.org/pypi/python-cjson
The module is written in C and it is up to 250 times faster when compared to the other python JSON implementations which are written directly in python. This speed gain varies with the complexity of the data and the operation and is the the range of 10-200 times for encoding operations and in the range of 100-250 times for decoding operations.
I'm :+1: for perf-investigate and improve the bottlenecks in st2client itself, instead of creating limits for users here and there.
@bigmstone We can also finally start re-writing st2client in Go :trollface:
armab
on 5 Sep 2017
@armab I don't totally agree with you.
There is a human-friendly output format (table one) and machine friendly one. They both serve different purposes. If someone wants to script against CLI they should use a machine readable format (json / yaml).
If they are using the default table output aka human-friendly one they are asking for troubles since that format can and will change (not to mention that it's hard to parse).
The problem with performance only comes up when using "human friendly" output format (table one). That output has a lot of overhead and is not meant to displays 100's and potentially 1000's of results (yes, we should still look into some easy performance gains by switching the json library, but IIRC, we already use simplejson which uses a C extension).
For that and for machine readable stuff we have json / yaml output format and flags.
So in short, I agree with @enykeev. By default when using human-friendly output format, we should display some reasonable number of items (e.g 50 / 100), but we should allow user to retrieve all the items.
This "disable" limit aka limit=0 should also be behind some RBAC wall (only available to admins) or similar to prevent potential DDoS in case there are many records in the database.
Kami
on 5 Sep 2017
The reasonable middle ground will be to load one pack at a time so instead of looking for a page for an action, we would only need its pack name which we already have. Problem with that approach, though, is outlined in this issue's description - loading even a single pack may take unacceptably long time.
I think that's a reasonable first step.
To avoid "too many actions in a pack" issue, we could use API based action name filtering and perhaps only display a specific action and not all of them by default.
Kami
on 5 Sep 2017
The problem with performance only comes up when using "human friendly" output format (table one).
@Kami Actually, from my timing results, the table format does not exhibit a performance problem, only the JSON and YAML formatting options do.
I actually agree with @armab here. As an end user i would really like to get a complete list of all the actions/packs/etc and not have to paginate anything. When i say st2 xxx list i expect a complete list.
In terms of it being not parseable, i hacked this together :)
st2 action list -a ref pack | head -n-1 | tail -n+4 | awk -F'|' '{gsub(/ /, "", $0); print $2}'
Now i have a newline delimited list of actions (fully qualified).
nmaludy
on 5 Sep 2017
@nmaludy
Thanks, in this case I need to look into JSON / YAML again (I just quickly tested it using curl last time).
At least for JSON the fix for the common use case (just using --json flag and no other flags) should be easy - we simply return JSON as returned by the API no need to to uneeded json.parse(json.dumps()) round-trip.
Kami
on 5 Sep 2017
I've gone ahead and run a profiler against the st2client code for these commands:
Results - Default
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 2.762 2.762 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:351(main)
1 0.001 0.001 2.643 2.643 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:275(run)
1 0.000 0.000 2.640 2.640 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/resource.py:255(run_and_print)
1 0.000 0.000 1.875 1.875 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/resource.py:37(decorate)
1 0.000 0.000 1.875 1.875 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/resource.py:281(run)
1 0.000 0.000 1.875 1.875 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/models/core.py:32(decorate)
1 0.001 0.001 1.875 1.875 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/models/core.py:167(get_all)
1 0.000 0.000 1.848 1.848 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/httpclient.py:29(decorate)
1 0.000 0.000 1.848 1.848 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/httpclient.py:38(decorate)
1 0.000 0.000 1.848 1.848 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/httpclient.py:85(get)
1 0.000 0.000 1.848 1.848 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/api.py:61(get)
1 0.000 0.000 1.848 1.848 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/api.py:16(request)
1 0.000 0.000 1.847 1.847 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/sessions.py:440(request)
1 0.000 0.000 1.845 1.845 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/sessions.py:599(send)
1 0.000 0.000 1.840 1.840 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/adapters.py:386(send)
1 0.000 0.000 1.839 1.839 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py:446(urlopen)
1 0.000 0.000 1.838 1.838 /opt/stackstorm/st2/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py:321(_make_request)
90 1.837 0.020 1.837 0.020 {method 'recv' of '_socket.socket' objects}
1 0.000 0.000 1.837 1.837 /usr/lib64/python2.7/httplib.py:1053(getresponse)
1 0.000 0.000 1.837 1.837 /usr/lib64/python2.7/httplib.py:437(begin)
15 0.000 0.000 1.837 0.122 /usr/lib64/python2.7/socket.py:406(readline)
1 0.000 0.000 1.837 1.837 /usr/lib64/python2.7/httplib.py:398(_read_status)
1 0.000 0.000 0.764 0.764 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:86(print_output)
2 0.002 0.001 0.727 0.364 /opt/stackstorm/st2/lib/python2.7/site-packages/prettytable.py:948(get_string)
1404 0.061 0.000 0.520 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/prettytable.py:1082(_stringify_row)
19518 0.033 0.000 0.432 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/prettytable.py:1327(_str_block_width)
1 0.000 0.000 0.406 0.406 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:74(format_output)
1 0.009 0.009 0.406 0.406 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/formatters/table.py:55(format)
Results - JSON
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 44.260 44.260 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:351(main)
1 0.001 0.001 44.141 44.141 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:275(run)
1 0.000 0.000 44.138 44.138 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/resource.py:255(run_and_print)
1 0.000 0.000 42.186 42.186 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:86(print_output)
1 0.000 0.000 42.183 42.183 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:74(format_output)
1 0.000 0.000 42.183 42.183 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/formatters/doc.py:54(format)
1 0.003 0.003 42.147 42.147 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/formatters/doc.py:33(format)
702 0.006 0.000 42.142 0.060 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/jsutil.py:28(get_kvps)
2106 0.009 0.000 42.136 0.020 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/jsutil.py:19(get_value)
2106 0.005 0.000 42.088 0.020 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:13(parse)
2106 0.007 0.000 42.080 0.020 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:30(parse)
2106 0.165 0.000 42.068 0.020 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:34(parse_token_stream)
2106 0.268 0.000 38.902 0.018 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:3214(yacc)
2106 0.034 0.000 32.962 0.016 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2100(__init__)
2106 5.421 0.003 29.708 0.014 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2533(lr_parse_table)
2072304 6.498 0.000 12.183 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2163(lr0_goto)
2106 1.055 0.001 10.773 0.005 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2198(lr0_items)
2106 0.023 0.000 9.769 0.005 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2509(add_lalr_lookaheads)
2106 2.694 0.001 4.872 0.002 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2371(compute_lookback_includes)
92664 2.172 0.000 3.589 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2137(lr0_closure)
2106 0.006 0.000 2.965 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:323(parse)
2106 0.073 0.000 2.960 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:1001(parseopt_notrack)
4212 0.014 0.000 2.826 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:177(token)
4212 0.005 0.000 2.812 0.001 {next}
Results - YAML
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 46.633 46.633 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:351(main)
1 0.001 0.001 46.514 46.514 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/shell.py:275(run)
1 0.000 0.000 46.510 46.510 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/resource.py:255(run_and_print)
1 0.000 0.000 44.606 44.606 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:86(print_output)
1 0.000 0.000 44.604 44.604 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/commands/__init__.py:74(format_output)
1 0.000 0.000 44.603 44.603 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/formatters/doc.py:62(format)
1 0.004 0.004 43.887 43.887 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/formatters/doc.py:33(format)
702 0.006 0.000 43.882 0.063 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/jsutil.py:28(get_kvps)
2106 0.009 0.000 43.876 0.021 /opt/stackstorm/st2/lib/python2.7/site-packages/st2client/utils/jsutil.py:19(get_value)
2106 0.005 0.000 43.827 0.021 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:13(parse)
2106 0.007 0.000 43.819 0.021 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:30(parse)
2106 0.161 0.000 43.807 0.021 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:34(parse_token_stream)
2106 0.266 0.000 40.545 0.019 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:3214(yacc)
2106 0.034 0.000 34.378 0.016 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2100(__init__)
2106 5.606 0.003 30.968 0.015 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2533(lr_parse_table)
2072304 6.765 0.000 12.672 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2163(lr0_goto)
2106 1.111 0.001 11.202 0.005 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2198(lr0_items)
2106 0.021 0.000 10.249 0.005 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2509(add_lalr_lookaheads)
2106 2.831 0.001 5.114 0.002 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2371(compute_lookback_includes)
92664 2.240 0.000 3.728 0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:2137(lr0_closure)
2106 0.006 0.000 3.065 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:323(parse)
2106 0.077 0.000 3.059 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/ply/yacc.py:1001(parseopt_notrack)
4212 0.016 0.000 2.923 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/parser.py:177(token)
4212 0.005 0.000 2.907 0.001 {next}
4212 0.032 0.000 2.902 0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/jsonpath_rw/lexer.py:22(tokenize)
@nmaludy reports bugs and fixes them :+1:
https://github.com/StackStorm/st2/pull/3854
armab
on 18 Dec 2017
Related issues
nmaludy
路
5Comments
makandre
路
8Comments
JohnWelborn
路
8Comments
Kami
路
8Comments
longfei-zhang
路
8Comments
Most helpful comment
Sadly, I can't agree here and noted the same before https://github.com/StackStorm/st2/issues/3708#issuecomment-326986207.
As ops people, we want to get all the results and then process | grep | pipe, do anything with data in most of the cases. Pagination is so confusing when you work with CLI on a prod server. Filtering output via st2 CLI itself helps, but not all the time.
Forcing pagination here would be another way to hide the problem under the rug.
If
jsonparsing is slow, can we investigate something likecjsonorujson,ijsoninstead and approaches like that?Example for
cjson:https://pypi.python.org/pypi/python-cjson
I'm :+1: for perf-investigate and improve the bottlenecks in
st2clientitself, instead of creating limits for users here and there.@bigmstone We can also finally start re-writing
st2clientinGo:trollface: