Combination of "eval set -- ..." and $() command substitution is slow
Configuration Information [Automatically generated, do not change]: Machine: x86_64 OS: linux-gnu Compiler: gcc Compilation CFLAGS: -g -O2 -fdebug-prefix-map=/tmp/bash/bash-5.0=. -fstack-protector-strong -Wformat -Werror=format-security -Wall -Wno-parentheses -Wno-format-security uname output: Linux $nodename 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u2 (2019-05-13) x86_64 GNU/Linux Machine Type: x86_64-pc-linux-gnu Bash Version: 5.0 Patch Level: 3 Release Status: release Description: I discovered a curious performance degradation in the combined usage of the constructs "eval set -- ..." and new-style command substitution. In short, setting the positional arguments via eval and then iterating over each one while performing $() command substitution(s) is significantly slower than not using eval, or not making command substitution, or using `` instead. I include below a reduced test script that illustrates the issue. A few notes: - The pathological case is "1 1 0". - I did not observe performance difference in unoptimised builds (-O0). Example output: case 0 0 X set real0m0.001s user0m0.000s sys 0m0.000s for loop real0m0.008s user0m0.008s sys 0m0.000s -- case 0 1 0 set real0m0.001s user0m0.000s sys 0m0.000s for loop cmdsubst-currency real0m0.551s user0m0.048s sys 0m0.144s -- case 0 1 1 set real0m0.001s user0m0.000s sys 0m0.000s for loop cmdsubst-grave real0m0.520s user0m0.048s sys 0m0.116s -- case 1 0 X eval set real0m0.002s user0m0.004s sys 0m0.000s for loop real0m0.008s user0m0.008s sys 0m0.000s -- case 1 1 0 eval set real0m0.002s user0m0.000s sys 0m0.000s for loop cmdsubst-currency real0m0.968s user0m0.432s sys 0m0.148s -- case 1 1 1 eval set real0m0.002s user0m0.004s sys 0m0.000s for loop cmdsubst-grave real0m0.529s user0m0.044s sys 0m0.124s -- Observations: - The pathological case "1 1 0" spends about 10 times more time doing something in userspace during the loop, relative to the comparable cases "0 1 0", "0 1 1", and "1 1 1". - $() seems generally slightly slower than ``, but becomes pathologically so when preceded with "eval set -- ...". - "eval set -- ..." itself doesn't seem slow at all, but obviously it has side-effects not captured by the "time" measurement tool. I tested an --enable-profiling build but the results are vastly different between test cases so I wasn't able to gain much insight by comparing them. (Also I'm inexperienced with gprof.) For reference, though, these are the top 10 functions in the flat listing for 3 of the test cases: case 0 1 0: % cumulative self self total time seconds secondscalls ms/call ms/call name 18.75 0.09 0.09 4801 0.02 0.02 make_child 13.54 0.16 0.07 1200 0.05 0.05 reap_dead_jobs 13.54 0.22 0.07 sigchld_handler 6.25 0.25 0.0338586 0.00 0.00 read_token.constprop.9 6.25 0.28 0.03 7259 0.00 0.04 param_expand 4.17 0.30 0.02 9609 0.00 0.01 yyparse 2.08 0.31 0.0128910 0.00 0.00 assignment 2.08 0.32 0.012 0.00 0.00 set_line_mbstate 2.08 0.33 0.0114417 0.00 0.00 set_signal_handler 2.08 0.34 0.01 9643 0.00 0.00 zread case 1 1 1: % cumulative self self total time seconds secondscalls us/call us/call name 31.03 0.09 0.09 480118.7518.75 make_child 15.52 0.14 0.05 120037.5037.50 reap_dead_jobs 15.52 0.18 0.05 sigchld_handler 6.90 0.20 0.02 9889 2.02 2.02 hash_search 3.45 0.21 0.0114464 0.69 0.69 dequote_string 3.45 0.22 0.01 8461 1.1816.14 param_expand 3.45 0.23 0.01 4808 2.08 3.12 run_sigchld_trap 3.45 0.24 0.01 4801 2.0823.05 command_substitute 3.45 0.25 0.01 4801 2.08 2.09 wait_for 3.45 0.26 0.01 4800 2.08 2.08 string_extract case 1 1 0 (pathological): % cumulative self self total time seconds secondscalls us/call us/
Re: Combination of "eval set -- ..." and $() command substitution is slow
Dear Chet Ramey, thanks for the explanations, I assume you were able to reproduce the issue. First a warning that I forgot to include in the previous email: the quoted excerpts of the gprof tables correspond to a slightly modified test script in which I tried to magnify the overhead in order to more easily spot performance differences. Therefore, the absolute values displayed, e.g. number of function calls, are exaggerated. The relative values (and hopefully your conclusions) remain largely the same, though. Sorry for any potential confusion. A few short comments prompted by your reply (probably not very useful, feel free to ignore them). Chet Ramey: >> - $() seems generally slightly slower than ``, but becomes pathologically >> so when preceded with "eval set -- ...". > > It is slightly slower -- POSIX requires that the shell parse the contents > of $(...) to determine that it's a valid script as part of finding the > closing `)'. The rules for finding the closing "`" don't have that > requirement. > >> - "eval set -- ..." itself doesn't seem slow at all, but obviously it has >> side-effects not captured by the "time" measurement tool. > > What happens is you end up with a 4900-character command string that you > have to parse multiple times. But that's not the worst of it. Since this statement ought to run exactly once, naïvely I would expect that by "multiple times" you really mean at most "twice": once for the top-level script, another time "inside" the eval "sub-script". > The gprof output provides a clue. > > >> case 1 1 0 (pathological): >>% cumulative self self total >> time seconds secondscalls us/call us/call name >> 38.89 0.21 0.2128890 7.27 7.27 set_line_mbstate > > set_line_mbstate() runs through each command line before parsing, creating > a bitmap that indicates whether each element is a single-byte character or > part of a multi-byte character. The scanner uses this to determine whether > a shell metacharacter should act as a delimiter or get skipped over as part > of a multibyte character. For a single run with args `1 1 0', it gets > called around 7300 times, with around 2400 of them for the 4900-character > string with all the arguments. > > When you're in a multibyte locale (en_US.UTF-8 is one such), each one of > those characters requires a call to mbrlen/mbrtowc. So that ends up being > 2400 * 4900 calls to mbrlen. I am indeed using an UTF-8 locale, but I tested also with export LC_ALL=C and the behaviour did not change, I should have mentioned that. Also, it occurs to me that since all shell metacharacters are surely 7-bit ASCII, and all UTF-8 code units are strictly and deliberately non-ASCII 8-bit bytes, at least in the case of UTF-8 it may not be necessary to construct such bitmap: there cannot be a shell-metacharacter byte part of a UTF-8 sequence representing something else, so there's no need for the distinction. Of course, this observation applies only to such specially crafted multibyte encodings as UTF-8 (which nonetheless is surely by far the most common). Furthermore, it does not explain the issue at hand. > There is something happening here -- there's no way there should be that > many calls to set_line_mbstate(), Notice that there are almost as many calls (only 2 fewer) in case "0 1 0" (in which eval is not used) yet in that case the performance is not harmed. Quoting from the previous email: case 0 1 0: 2.08 0.32 0.012 0.00 0.00 set_line_mbstate case 1 1 0 (pathological): 38.89 0.21 0.2128890 7.27 7.27 set_line_mbstate OTOH, all other test cases show less than 100 calls (these numbers correspond to a profiling run of the given script, unmodified): $ grep -m1 set_line_mbstate gmon*.table gmon.out.0-0-X.table: 0.00 0.00 0.00 88 0.00 0.00 set_line_mbstate gmon.out.0-1-0.table: 0.00 0.13 0.00 7288 0.00 0.00 set_line_mbstate gmon.out.0-1-1.table: 0.00 0.18 0.00 88 0.00 0.00 set_line_mbstate gmon.out.1-0-X.table: 0.00 0.01 0.00 90 0.00 0.00 set_line_mbstate gmon.out.1-1-0.table: 37.50 0.06 0.06 7290 8.23 8.23 set_line_mbstate gmon.out.1-1-1.table: 0.00 0.07 0.00 90 0.00 0.00 set_line_mbstate > even when you have to save and restore > the input line because you have to parse the contents of $(). There must > be some combination of the effect of `eval' on the line bitmap and the > long string. I'll see what I can figure out. > > Chet Cheers.
backquote peculiarities (was: Re: Combination of "eval set -- ..." and $() command substitution is slow)
Robert Elz: > Date:Wed, 10 Jul 2019 17:21:00 + > From: astian > Message-ID: > > I doubt it makes any difference to the timing, which I think > Chet has already answered, but it is worth pointing out that these > two commands ... > > printf '%s\n' "`printf %s "$i"`" > printf '%s\n' "$(printf %s "$i")" > > which (I believe)) are supposed to be the same thing, using the > different (ancient, and modern) forms of command substitution aren't > actually the same. In the first $i is unquoted, in the second it is > quoted. Here, since its value is just a number and IFS isn't being > fiddled, there is not likely to be any effect, but if you really > want to make those two the same, the first needs to be written as > > printf '%s\n' "`printf %s \"$i\"`" > > Such are the joys of `` command substitutions (just avoid them). > > kre Dear Robert Elz, I'm aware of several of its peculiarities and I typically do avoid them. However, is it true that $i is unquoted in the first case? Consider: i='foo bar' set -x printf '%s\n' "`printf '<%s>' "$i"`" printf '%s\n' "`printf '<%s>' \"$i\"`" printf '%s\n' "`printf '<%s>' $i`" Which outputs: ++ printf '<%s>' 'foo bar' + printf '%s\n' '' ++ printf '<%s>' 'foo bar' + printf '%s\n' '' ++ printf '<%s>' foo bar + printf '%s\n' '' Cheers.
Re: backquote peculiarities
Chet Ramey:
> On 7/15/19 6:19 PM, astian wrote:
>
>>> I doubt it makes any difference to the timing, which I think
>>> Chet has already answered, but it is worth pointing out that these
>>> two commands ...
>>>
>>> printf '%s\n' "`printf %s "$i"`"
>>> printf '%s\n' "$(printf %s "$i")"
>>>
>>> which (I believe)) are supposed to be the same thing, using the
>>> different (ancient, and modern) forms of command substitution aren't
>>> actually the same. In the first $i is unquoted, in the second it is
>>> quoted. Here, since its value is just a number and IFS isn't being
>>> fiddled, there is not likely to be any effect, but if you really
>>> want to make those two the same, the first needs to be written as
>>>
>>> printf '%s\n' "`printf %s \"$i\"`"
>>>
>>> Such are the joys of `` command substitutions (just avoid them).
>>>
>>> kre
>>
>> Dear Robert Elz, I'm aware of several of its peculiarities and I typically do
>> avoid them. However, is it true that $i is unquoted in the first case?
>
> POSIX makes it undefined behavior, and different shells do it differently.
> Bash makes the $i quoted within the `` string, as you discovered.
Ah, thanks for the clarification. I wonder if the excerpt below (particularly
the last sentence) would be the relevant wording of POSIX, i.e. that some
shells might interpret the command as the concatenation of a double-quoted
string, the unquoted $i, and another double-quoted string:
"`printf %s "$i"`" => CONCAT("`printf %s ", $i, "`")
Which would then lead to "undefined results".
Cheers.
---
2.2.3 Double-Quotes [0]
Enclosing characters in double-quotes ( "" ) shall preserve the literal value
of all characters within the double-quotes, with the exception of the
characters backquote, , and , as follows:
[...]
`
The backquote shall retain its special meaning introducing the other
form of command substitution (see Command Substitution). [...] Either of
the following cases produces undefined results:
- A single-quoted or double-quoted string that begins, but does not
end, within the "`...`" sequence
- A "`...`" sequence that begins, but does not end, within the same
double-quoted string
[...]
0:
https://pubs.opengroup.org/onlinepubs/9699919799/utilities/V3_chap02.html#tag_18_02_03
