| Message ID | Y7dUo6woh9Y31cdl@mail.google.com (mailing list archive) |
|---|---|
| State | Changes Requested |
| Headers | show |
| Series | trace-cmd: document expected behaviour of execvp for record command | expand |
On Fri, 6 Jan 2023 11:52:19 +1300 Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> wrote: > In tracecmd/trace-record.c:<run_cmd>, trace-cmd record -F <executable> > is launched via the libc's execvp() routine. > > If you run a command which is meant to be found in one of the entries > of the PATH env var then you should see <n> invocations of the > __x64_sys_execve() syscall where <n> will be equal to the number of > attempts that execvp() routine had done until it could find the > executable. > > While the routine works as expected, its behaviour can seem a bit > cryptic for untrained eyes and makes one wonder whether there is > something wrong in any of the parts involved in the tracing operation. > Some time after one digs into trace-cmd's and libc's code base, one > realises that everything is working as expected but documenting it could > save other people's time :-) > > Document the expected behaviour ftrace users should see depending on > the way -F <executable> is used. > > Signed-off-by: Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> > --- > Additional context: > > - absolute path example: > > # trace-cmd record -p function_graph \ > -g __x64_sys_execve -O nofuncgraph-irqs \ > -n __cond_resched --max-graph-depth 1 \ > -F /usr/bin/echo "ftrace" > /dev/null > > # trace-cmd report > echo-172994 [000] 185539.798539: funcgraph_entry: ! 803.376 us | __x64_sys_execve(); > > - PATH-dependent path example: > > # trace-cmd record -p function_graph \ > -g __x64_sys_execve -O nofuncgraph-irqs \ > -n __cond_resched --max-graph-depth 1 \ > -F echo "ftrace" > /dev/null > > # trace-cmd report > echo-172656 [002] 185009.671586: funcgraph_entry: ! 288.732 us | __x64_sys_execve(); > echo-172656 [002] 185009.671879: funcgraph_entry: ! 158.337 us | __x64_sys_execve(); > echo-172656 [002] 185009.672042: funcgraph_entry: ! 161.843 us | __x64_sys_execve(); > echo-172656 [002] 185009.672207: funcgraph_entry: ! 157.656 us | __x64_sys_execve(); > echo-172656 [002] 185009.672369: funcgraph_entry: ! 156.343 us | __x64_sys_execve(); > echo-172656 [002] 185009.672529: funcgraph_entry: ! 863.629 us | __x64_sys_execve(); Honestly, the above should be in the change log. > > --- > Documentation/trace-cmd/trace-cmd-record.1.txt | 4 ++++ > 1 file changed, 4 insertions(+) > > diff --git a/Documentation/trace-cmd/trace-cmd-record.1.txt b/Documentation/trace-cmd/trace-cmd-record.1.txt > index b709e48..a000cbe 100644 > --- a/Documentation/trace-cmd/trace-cmd-record.1.txt > +++ b/Documentation/trace-cmd/trace-cmd-record.1.txt > @@ -113,6 +113,10 @@ OPTIONS > Using *-F* will let you trace only events that are caused by the given > command. > > + Note: if the specified filename is neither absolute or relative then libc > + will invoke execve() syscall for every entry in the colon-separated list of > + directory pathnames specified in the PATH environment variable. > + Hmm, do you think it may be worth open-coding execvp() and looking for it from trace-cmd, and then only enabling tracing when it found the full path? -- Steve > *-P* 'pid':: > Similar to *-F* but lets you specify a process ID to trace. >
On Thu, Jan 05, 2023 at 06:13:17PM -0500, Steven Rostedt wrote: > On Fri, 6 Jan 2023 11:52:19 +1300 > Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> wrote: > > > In tracecmd/trace-record.c:<run_cmd>, trace-cmd record -F <executable> > > is launched via the libc's execvp() routine. > > > > If you run a command which is meant to be found in one of the entries > > of the PATH env var then you should see <n> invocations of the > > __x64_sys_execve() syscall where <n> will be equal to the number of > > attempts that execvp() routine had done until it could find the > > executable. > > > > While the routine works as expected, its behaviour can seem a bit > > cryptic for untrained eyes and makes one wonder whether there is > > something wrong in any of the parts involved in the tracing operation. > > Some time after one digs into trace-cmd's and libc's code base, one > > realises that everything is working as expected but documenting it could > > save other people's time :-) > > > > Document the expected behaviour ftrace users should see depending on > > the way -F <executable> is used. > > > > Signed-off-by: Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> > > --- > > Additional context: > > > > - absolute path example: > > > > # trace-cmd record -p function_graph \ > > -g __x64_sys_execve -O nofuncgraph-irqs \ > > -n __cond_resched --max-graph-depth 1 \ > > -F /usr/bin/echo "ftrace" > /dev/null > > > > # trace-cmd report > > echo-172994 [000] 185539.798539: funcgraph_entry: ! 803.376 us | __x64_sys_execve(); > > > > - PATH-dependent path example: > > > > # trace-cmd record -p function_graph \ > > -g __x64_sys_execve -O nofuncgraph-irqs \ > > -n __cond_resched --max-graph-depth 1 \ > > -F echo "ftrace" > /dev/null > > > > # trace-cmd report > > echo-172656 [002] 185009.671586: funcgraph_entry: ! 288.732 us | __x64_sys_execve(); > > echo-172656 [002] 185009.671879: funcgraph_entry: ! 158.337 us | __x64_sys_execve(); > > echo-172656 [002] 185009.672042: funcgraph_entry: ! 161.843 us | __x64_sys_execve(); > > echo-172656 [002] 185009.672207: funcgraph_entry: ! 157.656 us | __x64_sys_execve(); > > echo-172656 [002] 185009.672369: funcgraph_entry: ! 156.343 us | __x64_sys_execve(); > > echo-172656 [002] 185009.672529: funcgraph_entry: ! 863.629 us | __x64_sys_execve(); > > Honestly, the above should be in the change log. Fair enough. I will send a new patch shortly. > > > > > --- > > Documentation/trace-cmd/trace-cmd-record.1.txt | 4 ++++ > > 1 file changed, 4 insertions(+) > > > > diff --git a/Documentation/trace-cmd/trace-cmd-record.1.txt b/Documentation/trace-cmd/trace-cmd-record.1.txt > > index b709e48..a000cbe 100644 > > --- a/Documentation/trace-cmd/trace-cmd-record.1.txt > > +++ b/Documentation/trace-cmd/trace-cmd-record.1.txt > > @@ -113,6 +113,10 @@ OPTIONS > > Using *-F* will let you trace only events that are caused by the given > > command. > > > > + Note: if the specified filename is neither absolute or relative then libc > > + will invoke execve() syscall for every entry in the colon-separated list of > > + directory pathnames specified in the PATH environment variable. > > + > > Hmm, do you think it may be worth open-coding execvp() and looking for it > from trace-cmd, and then only enabling tracing when it found the full path? > > -- Steve That's a good point. I thought about it for a while and this is really a pickle. I'll dump the things I'm thinking about and peharps you can help me choosing between the approaches :-) Launching executables via: libc->execvp: It avoid some sorts of TOCTOU race conditions by trying to execve executables and leave it up to the kernel to do a 'single' file-exists validation (best case scenario) instead of validate whether file exists twice, once in user-space and again in kernel (best case scenario). bash: As a counter point (and also because that's most likely how trace-cmd will be executed). Bash actually does the open-coding execvp() approach as shown below: # trace-cmd record -p function_graph \ -g __x64_sys_execve -O nofuncgraph-irqs \ --max-graph-depth 1 \ -F /usr/bin/bash -c "ls" > /dev/null ls-178525 [010] 197387.772776: funcgraph_entry: ! 775.074 us | __x64_sys_execve(); # for /usr/bin/bash ls-178525 [010] 197387.775568: funcgraph_entry: ! 993.453 us | __x64_sys_execve(); # for /usr/bin/ls I guess this will boil down to whether you want to make trace-cmd as 'transparent' as possible (in comparison to running the command without prepending trace-cmd) OR if you actually care about/want to abide by the TOCTOU 'guarantees' that libc implements for userspace applications Let me know your thoughts. I'm flexible with either approach - Paulo Almeida > > > > *-P* 'pid':: > > Similar to *-F* but lets you specify a process ID to trace. > > >
On Fri, 6 Jan 2023 15:09:58 +1300 Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> wrote: > That's a good point. I thought about it for a while and this is really a pickle. > > I'll dump the things I'm thinking about and peharps you can help me > choosing between the approaches :-) > > Launching executables via: > > libc->execvp: It avoid some sorts of TOCTOU race conditions by trying to > execve executables and leave it up to the kernel to do a 'single' > file-exists validation (best case scenario) instead of validate whether > file exists twice, once in user-space and again in kernel (best case > scenario). > > bash: As a counter point (and also because that's most > likely how trace-cmd will be executed). Bash actually does the > open-coding execvp() approach as shown below: > > # trace-cmd record -p function_graph \ > -g __x64_sys_execve -O nofuncgraph-irqs \ > --max-graph-depth 1 \ > -F /usr/bin/bash -c "ls" > /dev/null > > > ls-178525 [010] 197387.772776: funcgraph_entry: ! 775.074 us | __x64_sys_execve(); # for /usr/bin/bash > ls-178525 [010] 197387.775568: funcgraph_entry: ! 993.453 us | __x64_sys_execve(); # for /usr/bin/ls > > I guess this will boil down to whether you want to make trace-cmd as > 'transparent' as possible (in comparison to running the command without > prepending trace-cmd) OR if you actually care about/want to abide by > the TOCTOU 'guarantees' that libc implements for userspace applications > > Let me know your thoughts. I'm flexible with either approach I think I rather do it the bash way. I don't believe TOCTOU is important here. -- Steve
diff --git a/Documentation/trace-cmd/trace-cmd-record.1.txt b/Documentation/trace-cmd/trace-cmd-record.1.txt index b709e48..a000cbe 100644 --- a/Documentation/trace-cmd/trace-cmd-record.1.txt +++ b/Documentation/trace-cmd/trace-cmd-record.1.txt @@ -113,6 +113,10 @@ OPTIONS Using *-F* will let you trace only events that are caused by the given command. + Note: if the specified filename is neither absolute or relative then libc + will invoke execve() syscall for every entry in the colon-separated list of + directory pathnames specified in the PATH environment variable. + *-P* 'pid':: Similar to *-F* but lets you specify a process ID to trace.
In tracecmd/trace-record.c:<run_cmd>, trace-cmd record -F <executable> is launched via the libc's execvp() routine. If you run a command which is meant to be found in one of the entries of the PATH env var then you should see <n> invocations of the __x64_sys_execve() syscall where <n> will be equal to the number of attempts that execvp() routine had done until it could find the executable. While the routine works as expected, its behaviour can seem a bit cryptic for untrained eyes and makes one wonder whether there is something wrong in any of the parts involved in the tracing operation. Some time after one digs into trace-cmd's and libc's code base, one realises that everything is working as expected but documenting it could save other people's time :-) Document the expected behaviour ftrace users should see depending on the way -F <executable> is used. Signed-off-by: Paulo Miguel Almeida <paulo.miguel.almeida.rodenas@gmail.com> --- Additional context: - absolute path example: # trace-cmd record -p function_graph \ -g __x64_sys_execve -O nofuncgraph-irqs \ -n __cond_resched --max-graph-depth 1 \ -F /usr/bin/echo "ftrace" > /dev/null # trace-cmd report echo-172994 [000] 185539.798539: funcgraph_entry: ! 803.376 us | __x64_sys_execve(); - PATH-dependent path example: # trace-cmd record -p function_graph \ -g __x64_sys_execve -O nofuncgraph-irqs \ -n __cond_resched --max-graph-depth 1 \ -F echo "ftrace" > /dev/null # trace-cmd report echo-172656 [002] 185009.671586: funcgraph_entry: ! 288.732 us | __x64_sys_execve(); echo-172656 [002] 185009.671879: funcgraph_entry: ! 158.337 us | __x64_sys_execve(); echo-172656 [002] 185009.672042: funcgraph_entry: ! 161.843 us | __x64_sys_execve(); echo-172656 [002] 185009.672207: funcgraph_entry: ! 157.656 us | __x64_sys_execve(); echo-172656 [002] 185009.672369: funcgraph_entry: ! 156.343 us | __x64_sys_execve(); echo-172656 [002] 185009.672529: funcgraph_entry: ! 863.629 us | __x64_sys_execve(); --- Documentation/trace-cmd/trace-cmd-record.1.txt | 4 ++++ 1 file changed, 4 insertions(+)