The general feeling I am getting from tracing the compounding is that we have to have the more granular tracing available (similar to this patch), and also (with followon patch) add noisier optional trace points lower down (that are generic) that we turn on less frequently (in particular when the filename is not good enough and we must have the xid - even if it makes the trace very noisy) On Tue, Mar 12, 2019 at 1:06 AM ronnie sahlberg <ronniesahlberg@xxxxxxxxx> wrote: > > Hmm. > > I don't think this is the wrong layer to add the tracing. > Instead of adding the tracing in say smb2_compound_op(), where we > create the compound, > I think it will be better to add the tracing down in the leaf > functions, i.e. down in SMB2_open_init(), SMB2_query_info_init(), ... > > That way we know that we will always have tracing for all opens/closes/... > > But then what to do about the trace_smb3_..._err()/trace_smb3_..._done() calls ? > These I think should be moved down and handled inside compound_send_recv(). > That way we can have one single place where we call the appropriate > _err()/_done() functions > and we know that we will catch every single completed function. > > I.e. just put it in a single place instead of in every single call-site. > In compound_send_recv we can just loop over all the responses, cast it > to a smb2_hdr structure, looka at both the command code as well as the > status code and call the appropriate xys_err() or xyz_done() functions > as needed. > > Let me show an example of what I mean for a open/query/close compound : > > trace_smb3_open_enter(xid=5, filename="foo", ...) from SMB2_open_init() > trace_smb3_query_info_enter(xid=5,... ) from SMB2_query_info_init() > trace_smb3_close_enter(xid=5, ...) from SMB2_close_init() > (maybe have additional tracing in compound_send_recv() that we are > about to send xid=5 to the wire) > trace_smb3_open_done(xid=5, ...) from compound_send_recv() > trace_smb3_query_info_done(xid=5, ...) from compound_send_recv() > trace_smb3_close_done(xid=5, ...) from compound_send_recv() > > > Now, we would not be able to immediately see the actual filename > anywhere else than in the initial trace_smb3_open_enter() since we no > longer have that available at the callsites that I suggest but do we > actually need that? > We can search on xid and match it all up. > Worst comes to it we could write a simple small tool that would > post-process the tracefile and add in these decorations. I.e. track > the xid numbers and the filename="foo" from the open_enter() > tracepoint and just inject them in all other tracepoints > where xid=5. > It would even have the benefit in that the log messages themselves > would become smaller since they would no longer need to contain the > filename for every single tracepoint. > Smaller is better :-) > > That post-processing tool could also much around in /proc/fs/cifs and > replace the decorations for ses->Suid, tcon->tid witht he actuall name > for the server and the share. > > > Just adding the _done()/_err() tracing to compound_send_recv() and we > will get tracing for every command completion today and in the future. > > > > > > On Tue, Mar 12, 2019 at 3:35 PM Steve French <smfrench@xxxxxxxxx> wrote: > > > > Version 2 of the patch attached. Here is sample output from running it: > > > > # entries-in-buffer/entries-written: 32/32 #P:8 > > # > > # _-----=> irqs-off > > # / _----=> need-resched > > # | / _---=> hardirq/softirq > > # || / _--=> preempt-depth > > # ||| / delay > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > # | | | |||| | | > > mkdir-31324 [001] .... 362773.434903: > > smb3_query_info_compound_enter: xid=7 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > mkdir-31324 [002] .... 362773.435588: > > smb3_query_info_compound_err: xid=7 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir rc=-2 > > mkdir-31324 [002] .... 362773.435607: smb3_mkdir_enter: > > xid=8 sid=0xdd73f8cb tid=0x65257d36 path=\newdir > > mkdir-31324 [002] .... 362773.436643: smb3_mkdir_done: > > xid=8 sid=0xdd73f8cb tid=0x65257d36 path=\newdir > > mkdir-31324 [002] .... 362773.436659: > > smb3_query_info_compound_enter: xid=8 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > mkdir-31324 [002] .... 362773.437414: > > smb3_query_info_compound_done: xid=8 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > mkdir-31326 [006] .... 362775.812007: > > smb3_query_info_compound_enter: xid=9 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > mkdir-31326 [006] .... 362775.812796: > > smb3_query_info_compound_done: xid=9 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > rmdir-31327 [003] .... 362781.753333: > > smb3_query_info_compound_enter: xid=10 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > rmdir-31327 [003] .... 362781.754057: > > smb3_query_info_compound_done: xid=10 sid=0xdd73f8cb tid=0x65257d36 > > path=\newdir > > rmdir-31327 [003] .... 362781.754080: smb3_rmdir_enter: > > xid=11 sid=0xdd73f8cb tid=0x65257d36 path=\newdir > > rmdir-31327 [003] .... 362781.755143: smb3_rmdir_done: > > xid=11 sid=0xdd73f8cb tid=0x65257d36 path=\newdir > > touch-31328 [006] .... 362793.339620: > > smb3_set_info_compound_enter: xid=13 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > touch-31328 [006] .... 362793.340342: > > smb3_set_info_compound_done: xid=13 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > ln-31329 [002] .... 362800.848959: > > smb3_query_info_compound_enter: xid=15 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile > > ln-31329 [002] .... 362800.849624: > > smb3_query_info_compound_err: xid=15 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile rc=-2 > > ln-31329 [002] .... 362800.849656: > > smb3_query_info_compound_enter: xid=16 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > ln-31329 [003] .... 362800.850318: > > smb3_query_info_compound_done: xid=16 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > ln-31329 [003] .... 362800.850370: > > smb3_query_info_compound_enter: xid=17 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile > > ln-31329 [003] .... 362800.850918: > > smb3_query_info_compound_err: xid=17 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile rc=-2 > > ln-31329 [003] .... 362800.850940: smb3_hardlink_enter: > > xid=18 sid=0xdd73f8cb tid=0x65257d36 path=\newfile > > ln-31329 [003] .... 362800.851669: smb3_hardlink_done: > > xid=18 sid=0xdd73f8cb tid=0x65257d36 path=\newfile > > gmain-2225 [004] .... 362800.851847: > > smb3_query_info_compound_enter: xid=19 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile > > gmain-2225 [005] .... 362800.852345: > > smb3_query_info_compound_done: xid=19 sid=0xdd73f8cb tid=0x65257d36 > > path=\linknewfile > > rm-31330 [003] .... 362806.483029: > > smb3_query_info_compound_enter: xid=20 sid=0xdd73f8cb tid=0x65257d36 > > path=\badfile > > rm-31330 [003] .... 362806.483654: > > smb3_query_info_compound_err: xid=20 sid=0xdd73f8cb tid=0x65257d36 > > path=\badfile rc=-2 > > rm-31330 [003] .... 362806.483704: > > smb3_query_info_compound_enter: xid=21 sid=0xdd73f8cb tid=0x65257d36 > > path=\badfile > > rm-31330 [003] .... 362806.484296: > > smb3_query_info_compound_err: xid=21 sid=0xdd73f8cb tid=0x65257d36 > > path=\badfile rc=-2 > > rm-31335 [004] .... 362811.895827: > > smb3_query_info_compound_enter: xid=22 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > rm-31335 [005] .... 362811.896533: > > smb3_query_info_compound_done: xid=22 sid=0xdd73f8cb tid=0x65257d36 > > path=\newfile > > rm-31335 [005] .... 362811.896575: smb3_delete_enter: > > xid=23 sid=0xdd73f8cb tid=0x65257d36 path=\newfile > > rm-31335 [005] .... 362811.897364: smb3_delete_done: > > xid=23 sid=0xdd73f8cb tid=0x65257d36 path=\newfile > > > > On Mon, Mar 11, 2019 at 5:31 PM Steve French <smfrench@xxxxxxxxx> wrote: > > > > > > On Mon, Mar 11, 2019 at 5:18 PM Pavel Shilovsky <piastryyy@xxxxxxxxx> wrote: > > > > > > > > пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@xxxxxxxxx>: > > > > > > > > > > Sample output from tracing various newly added dynamic trace points > > > > > (with this patch) > > > > > > > > > > (trace-cmd record -e *query_info_co* -e smb3_hardlink* -e > > > > > smb3_rename* -e smb3_set_eof* -e smb3_set_info_co* -e smb3_mkdir* -e > > > > > smb3_delete*) > > > > > > > > > > # entries-in-buffer/entries-written: 44/44 #P:8 > > > > > # > > > > > # _-----=> irqs-off > > > > > # / _----=> need-resched > > > > > # | / _---=> hardirq/softirq > > > > > # || / _--=> preempt-depth > > > > > # ||| / delay > > > > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > > > > # | | | |||| | | > > > > > gvfsd-trash-2224 [004] .... 333095.401381: > > > > > smb3_query_info_compound_enter: xid=5 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > gvfsd-trash-2224 [002] .... 333095.402056: > > > > > smb3_query_info_compound_err: xid=5 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > gvfsd-trash-2224 [002] .... 333095.402189: > > > > > smb3_query_info_compound_enter: xid=6 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > gvfsd-trash-2224 [002] .... 333095.402688: > > > > > smb3_query_info_compound_err: xid=6 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > mkdir-16324 [002] .... 333123.559043: > > > > > smb3_query_info_compound_enter: xid=7 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16324 [003] .... 333123.559654: > > > > > smb3_query_info_compound_err: xid=7 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > mkdir-16324 [003] .... 333123.559673: smb3_mkdir_enter: > > > > > xid=8 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16324 [003] .... 333123.560748: smb3_mkdir_done: > > > > > xid=8 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16324 [003] .... 333123.560763: > > > > > smb3_query_info_compound_enter: xid=8 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16324 [003] .... 333123.561516: > > > > > smb3_query_info_compound_done: xid=8 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16325 [002] .... 333126.841897: > > > > > smb3_query_info_compound_enter: xid=9 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16325 [003] .... 333126.842580: > > > > > smb3_query_info_compound_err: xid=9 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > mkdir-16325 [003] .... 333126.842601: smb3_mkdir_enter: > > > > > xid=10 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16325 [003] .... 333126.843513: smb3_mkdir_done: > > > > > xid=10 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16325 [003] .... 333126.843529: > > > > > smb3_query_info_compound_enter: xid=10 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16325 [003] .... 333126.844251: > > > > > smb3_query_info_compound_done: xid=10 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16326 [000] .... 333129.858413: > > > > > smb3_query_info_compound_enter: xid=11 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > mkdir-16326 [000] .... 333129.859193: > > > > > smb3_query_info_compound_done: xid=11 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rmdir-16328 [007] .... 333138.828049: > > > > > smb3_query_info_compound_enter: xid=12 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rmdir-16328 [007] .... 333138.828827: > > > > > smb3_query_info_compound_done: xid=12 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rmdir-16329 [006] .... 333141.388154: > > > > > smb3_query_info_compound_enter: xid=14 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rmdir-16329 [006] .... 333141.388813: > > > > > smb3_query_info_compound_err: xid=14 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > rm-16340 [006] .... 333157.935975: > > > > > smb3_query_info_compound_enter: xid=15 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16340 [006] .... 333157.936607: > > > > > smb3_query_info_compound_err: xid=15 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > rm-16340 [006] .... 333157.936652: > > > > > smb3_query_info_compound_enter: xid=16 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16340 [006] .... 333157.937146: > > > > > smb3_query_info_compound_err: xid=16 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > touch-16349 [005] .... 333184.932302: > > > > > smb3_set_info_compound_enter: xid=18 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > touch-16349 [005] .... 333184.938303: > > > > > smb3_set_info_compound_done: xid=18 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16350 [003] .... 333187.920309: > > > > > smb3_query_info_compound_enter: xid=20 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16350 [003] .... 333187.920999: > > > > > smb3_query_info_compound_done: xid=20 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16350 [003] .... 333187.921043: smb3_delete_enter: > > > > > xid=21 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rm-16350 [003] .... 333187.921870: smb3_delete_done: > > > > > xid=21 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > touch-16361 [005] .... 333237.447252: > > > > > smb3_set_info_compound_enter: xid=23 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > touch-16361 [005] .... 333237.448044: > > > > > smb3_set_info_compound_done: xid=23 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [000] .... 333250.734035: > > > > > smb3_query_info_compound_enter: xid=25 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [001] .... 333250.734689: > > > > > smb3_query_info_compound_err: xid=25 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > ln-16366 [001] .... 333250.734735: > > > > > smb3_query_info_compound_enter: xid=26 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [001] .... 333250.735368: > > > > > smb3_query_info_compound_done: xid=26 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [001] .... 333250.735413: > > > > > smb3_query_info_compound_enter: xid=27 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [001] .... 333250.735947: > > > > > smb3_query_info_compound_err: xid=27 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > rc=-2 > > > > > ln-16366 [001] .... 333250.735973: smb3_hardlink_enter: > > > > > xid=28 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > ln-16366 [001] .... 333250.736679: smb3_hardlink_done: > > > > > xid=28 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > gmain-2225 [000] .... 333250.736855: > > > > > smb3_query_info_compound_enter: xid=29 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > gmain-2225 [001] .... 333250.737527: > > > > > smb3_query_info_compound_done: xid=29 sid=0xbb2583e9 tid=0xe7ab49dc > > > > > > > > Let's add full paths to the logs to increase usability - this way we > > > > can match logs with particular actions in the user space. > > > > > > ok - will add > > > > > > > Also please don't remove the blank line - the 2nd change in the patch: > > > > > > That was a typo - will fix > > > > > > > > > > > > -- > > > Thanks, > > > > > > Steve > > > > > > > > -- > > Thanks, > > > > Steve -- Thanks, Steve
