| Message ID | CAH2r5muY3xgVW03Mi8N-c4wyZFikzTeZgLDEuGLoXFXNZ-wFHA@mail.gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [SMB3] Add various dynamic tracepoints for compounded operations | expand |
пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@gmail.com>: > > 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. Also please don't remove the blank line - the 2nd change in the patch: @@ -104,7 +114,6 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, memset(&qi_iov, 0, sizeof(qi_iov)); rqst[num_rqst].rq_iov = qi_iov; rqst[num_rqst].rq_nvec = 1; - rc = SMB2_query_info_init(tcon, &rqst[num_rqst], COMPOUND_FID, COMPOUND_FID, FILE_ALL_INFORMATION, SMB2_O_INFO_FILE, 0, -- Best regards, Pavel Shilovsky
On Mon, Mar 11, 2019 at 5:18 PM Pavel Shilovsky <piastryyy@gmail.com> wrote: > > пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@gmail.com>: > > > > 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
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@gmail.com> wrote:
>
> On Mon, Mar 11, 2019 at 5:18 PM Pavel Shilovsky <piastryyy@gmail.com> wrote:
> >
> > пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@gmail.com>:
> > >
> > > 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
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@gmail.com> 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@gmail.com> wrote: > > > > On Mon, Mar 11, 2019 at 5:18 PM Pavel Shilovsky <piastryyy@gmail.com> wrote: > > > > > > пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@gmail.com>: > > > > > > > > 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
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@gmail.com> 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@gmail.com> 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@gmail.com> wrote: > > > > > > On Mon, Mar 11, 2019 at 5:18 PM Pavel Shilovsky <piastryyy@gmail.com> wrote: > > > > > > > > пн, 11 мар. 2019 г. в 14:25, Steve French <smfrench@gmail.com>: > > > > > > > > > > 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
I actually like the idea proposed in the patch: this way we will be able to track logical operations better. In a case we need a deeper logging we already have mid traces which contains MID, TID, SID and CMD - everything you need to trace individual SMB packet regardless of whether it is a part of compounding chain or not. Now in order to match both logical operation and SMB packets traces we need something common - like XID. Currently we do not propagate XID down to the transport layer, let's do that - this way we can trace individual system call from the very beginning to the completeness on every layer inside cifs.ko. вт, 12 мар. 2019 г. в 00:19, Steve French <smfrench@gmail.com>: > > 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@gmail.com> 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() > > As pointed above we already have a similar tracing inside compound_send_recv and other transport layer functions - command level tracing. The only problem is that we do not log failure cases when we didn't send the packet - we only log server responses in map_smb2_to_linux_error. This is another area of the tracing where a fix is needed. -- Best regards, Pavel Shilovsky
Version 3 of the patch attached. Sample output below:
(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* -e smb3_rmdir*)
mkdir-17927 [003] .... 447434.636544:
smb3_query_info_compound_enter: xid=7 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17927 [003] .... 447434.637240:
smb3_query_info_compound_err: xid=7 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
mkdir-17942 [000] .... 447446.807606:
smb3_query_info_compound_enter: xid=8 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17942 [000] .... 447446.808233:
smb3_query_info_compound_err: xid=8 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
mkdir-17942 [000] .... 447446.808251: smb3_mkdir_enter:
xid=9 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir
mkdir-17942 [000] .... 447446.809161: smb3_mkdir_done:
xid=9 sid=0x7dc5fd6f tid=0xc7968732
mkdir-17942 [000] .... 447446.809178:
smb3_query_info_compound_enter: xid=9 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17942 [000] .... 447446.809979:
smb3_query_info_compound_done: xid=9 sid=0x7dc5fd6f tid=0xc7968732
rmdir-17943 [001] .... 447451.374029:
smb3_query_info_compound_enter: xid=10 sid=0x7dc5fd6f tid=0xc7968732
path=\baddir
rmdir-17943 [001] .... 447451.379621:
smb3_query_info_compound_err: xid=10 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
rmdir-17944 [001] .... 447456.088795:
smb3_query_info_compound_enter: xid=11 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
rmdir-17944 [001] .... 447456.089615:
smb3_query_info_compound_done: xid=11 sid=0x7dc5fd6f tid=0xc7968732
rmdir-17944 [001] .... 447456.089640: smb3_rmdir_enter:
xid=12 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir
rmdir-17944 [001] .... 447456.090651: smb3_rmdir_done:
xid=12 sid=0x7dc5fd6f tid=0xc7968732
touch-17945 [006] .... 447460.575789:
smb3_set_info_compound_enter: xid=14 sid=0x7dc5fd6f tid=0xc7968732
path=\file
touch-17945 [006] .... 447460.576571:
smb3_set_info_compound_done: xid=14 sid=0x7dc5fd6f tid=0xc7968732
ln-17946 [001] .... 447468.254480:
smb3_query_info_compound_enter: xid=16 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
ln-17946 [001] .... 447468.255082:
smb3_query_info_compound_err: xid=16 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
ln-17946 [001] .... 447468.255118:
smb3_query_info_compound_enter: xid=17 sid=0x7dc5fd6f tid=0xc7968732
path=\file
ln-17946 [001] .... 447468.255715:
smb3_query_info_compound_done: xid=17 sid=0x7dc5fd6f tid=0xc7968732
ln-17946 [001] .... 447468.255760:
smb3_query_info_compound_enter: xid=18 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
ln-17946 [001] .... 447468.256254:
smb3_query_info_compound_err: xid=18 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
ln-17946 [001] .... 447468.256277: smb3_hardlink_enter:
xid=19 sid=0x7dc5fd6f tid=0xc7968732 path=\file
ln-17946 [001] .... 447468.256954: smb3_hardlink_done:
xid=19 sid=0x7dc5fd6f tid=0xc7968732
gmain-2225 [004] .... 447468.257130:
smb3_query_info_compound_enter: xid=20 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
gmain-2225 [005] .... 447468.257788:
smb3_query_info_compound_done: xid=20 sid=0x7dc5fd6f tid=0xc7968732
On Tue, Mar 12, 2019 at 4:51 PM Pavel Shilovsky <piastryyy@gmail.com> wrote:
>
> I actually like the idea proposed in the patch: this way we will be
> able to track logical operations better. In a case we need a deeper
> logging we already have mid traces which contains MID, TID, SID and
> CMD - everything you need to trace individual SMB packet regardless of
> whether it is a part of compounding chain or not.
>
> Now in order to match both logical operation and SMB packets traces we
> need something common - like XID. Currently we do not propagate XID
> down to the transport layer, let's do that - this way we can trace
> individual system call from the very beginning to the completeness on
> every layer inside cifs.ko.
>
> вт, 12 мар. 2019 г. в 00:19, Steve French <smfrench@gmail.com>:
> >
> > 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@gmail.com> 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()
> > >
>
> As pointed above we already have a similar tracing inside
> compound_send_recv and other transport layer functions - command level
> tracing. The only problem is that we do not log failure cases when we
> didn't send the packet - we only log server responses in
> map_smb2_to_linux_error. This is another area of the tracing where a
> fix is needed.
>
> --
> Best regards,
> Pavel Shilovsky
Reviewed-by me. Only issue is that it is very verbose like this : + if (rc) + trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid); We can do this late but this pattern can be simplified to a single line with a macro. It is always rc that decides which tracepoint we use, and the error path tracepoint has a small subset of the arguments,except for rc, than the _done tracepoint have. So the macro could take both rc as well as all the arguments for _done as this : TRACE_SMB3_RMDIR_END(rc, xid, suid, tid) which then expands to the four lines of code. We can do that later, just to reduce the amount of emacs real-estate these lines take up. On Wed, Mar 13, 2019 at 3:03 PM Steve French <smfrench@gmail.com> wrote: > > Version 3 of the patch attached. Sample output below: > (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* -e smb3_rmdir*) > > mkdir-17927 [003] .... 447434.636544: > smb3_query_info_compound_enter: xid=7 sid=0x7dc5fd6f tid=0xc7968732 > path=\newdir > mkdir-17927 [003] .... 447434.637240: > smb3_query_info_compound_err: xid=7 sid=0x7dc5fd6f tid=0xc7968732 > rc=-2 > mkdir-17942 [000] .... 447446.807606: > smb3_query_info_compound_enter: xid=8 sid=0x7dc5fd6f tid=0xc7968732 > path=\newdir > mkdir-17942 [000] .... 447446.808233: > smb3_query_info_compound_err: xid=8 sid=0x7dc5fd6f tid=0xc7968732 > rc=-2 > mkdir-17942 [000] .... 447446.808251: smb3_mkdir_enter: > xid=9 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir > mkdir-17942 [000] .... 447446.809161: smb3_mkdir_done: > xid=9 sid=0x7dc5fd6f tid=0xc7968732 > mkdir-17942 [000] .... 447446.809178: > smb3_query_info_compound_enter: xid=9 sid=0x7dc5fd6f tid=0xc7968732 > path=\newdir > mkdir-17942 [000] .... 447446.809979: > smb3_query_info_compound_done: xid=9 sid=0x7dc5fd6f tid=0xc7968732 > rmdir-17943 [001] .... 447451.374029: > smb3_query_info_compound_enter: xid=10 sid=0x7dc5fd6f tid=0xc7968732 > path=\baddir > rmdir-17943 [001] .... 447451.379621: > smb3_query_info_compound_err: xid=10 sid=0x7dc5fd6f tid=0xc7968732 > rc=-2 > rmdir-17944 [001] .... 447456.088795: > smb3_query_info_compound_enter: xid=11 sid=0x7dc5fd6f tid=0xc7968732 > path=\newdir > rmdir-17944 [001] .... 447456.089615: > smb3_query_info_compound_done: xid=11 sid=0x7dc5fd6f tid=0xc7968732 > rmdir-17944 [001] .... 447456.089640: smb3_rmdir_enter: > xid=12 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir > rmdir-17944 [001] .... 447456.090651: smb3_rmdir_done: > xid=12 sid=0x7dc5fd6f tid=0xc7968732 > touch-17945 [006] .... 447460.575789: > smb3_set_info_compound_enter: xid=14 sid=0x7dc5fd6f tid=0xc7968732 > path=\file > touch-17945 [006] .... 447460.576571: > smb3_set_info_compound_done: xid=14 sid=0x7dc5fd6f tid=0xc7968732 > ln-17946 [001] .... 447468.254480: > smb3_query_info_compound_enter: xid=16 sid=0x7dc5fd6f tid=0xc7968732 > path=\linkedfile > ln-17946 [001] .... 447468.255082: > smb3_query_info_compound_err: xid=16 sid=0x7dc5fd6f tid=0xc7968732 > rc=-2 > ln-17946 [001] .... 447468.255118: > smb3_query_info_compound_enter: xid=17 sid=0x7dc5fd6f tid=0xc7968732 > path=\file > ln-17946 [001] .... 447468.255715: > smb3_query_info_compound_done: xid=17 sid=0x7dc5fd6f tid=0xc7968732 > ln-17946 [001] .... 447468.255760: > smb3_query_info_compound_enter: xid=18 sid=0x7dc5fd6f tid=0xc7968732 > path=\linkedfile > ln-17946 [001] .... 447468.256254: > smb3_query_info_compound_err: xid=18 sid=0x7dc5fd6f tid=0xc7968732 > rc=-2 > ln-17946 [001] .... 447468.256277: smb3_hardlink_enter: > xid=19 sid=0x7dc5fd6f tid=0xc7968732 path=\file > ln-17946 [001] .... 447468.256954: smb3_hardlink_done: > xid=19 sid=0x7dc5fd6f tid=0xc7968732 > gmain-2225 [004] .... 447468.257130: > smb3_query_info_compound_enter: xid=20 sid=0x7dc5fd6f tid=0xc7968732 > path=\linkedfile > gmain-2225 [005] .... 447468.257788: > smb3_query_info_compound_done: xid=20 sid=0x7dc5fd6f tid=0xc7968732 > > On Tue, Mar 12, 2019 at 4:51 PM Pavel Shilovsky <piastryyy@gmail.com> wrote: > > > > I actually like the idea proposed in the patch: this way we will be > > able to track logical operations better. In a case we need a deeper > > logging we already have mid traces which contains MID, TID, SID and > > CMD - everything you need to trace individual SMB packet regardless of > > whether it is a part of compounding chain or not. > > > > Now in order to match both logical operation and SMB packets traces we > > need something common - like XID. Currently we do not propagate XID > > down to the transport layer, let's do that - this way we can trace > > individual system call from the very beginning to the completeness on > > every layer inside cifs.ko. > > > > вт, 12 мар. 2019 г. в 00:19, Steve French <smfrench@gmail.com>: > > > > > > 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@gmail.com> 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() > > > > > > > > As pointed above we already have a similar tracing inside > > compound_send_recv and other transport layer functions - command level > > tracing. The only problem is that we do not log failure cases when we > > didn't send the packet - we only log server responses in > > map_smb2_to_linux_error. This is another area of the tracing where a > > fix is needed. > > > > -- > > Best regards, > > Pavel Shilovsky > > > > -- > Thanks, > > Steve
I agree that we could use macros to shrink this - but as long as it is readable, seems fine to me. On Wed, Mar 13, 2019 at 12:38 AM ronnie sahlberg <ronniesahlberg@gmail.com> wrote: > > Reviewed-by me. > > Only issue is that it is very verbose like this : > + if (rc) > + trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc); > + else > + trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid); > > We can do this late but this pattern can be simplified to a single > line with a macro. > It is always rc that decides which tracepoint we use, and the error > path tracepoint has a small subset of the arguments,except for rc, > than the _done tracepoint have. > So the macro could take both rc as well as all the arguments for _done as this : > > TRACE_SMB3_RMDIR_END(rc, xid, suid, tid) > > which then expands to the four lines of code. > We can do that later, just to reduce the amount of emacs real-estate > these lines take up. > > > On Wed, Mar 13, 2019 at 3:03 PM Steve French <smfrench@gmail.com> wrote: > > > > Version 3 of the patch attached. Sample output below: > > (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* -e smb3_rmdir*) > > > > mkdir-17927 [003] .... 447434.636544: > > smb3_query_info_compound_enter: xid=7 sid=0x7dc5fd6f tid=0xc7968732 > > path=\newdir > > mkdir-17927 [003] .... 447434.637240: > > smb3_query_info_compound_err: xid=7 sid=0x7dc5fd6f tid=0xc7968732 > > rc=-2 > > mkdir-17942 [000] .... 447446.807606: > > smb3_query_info_compound_enter: xid=8 sid=0x7dc5fd6f tid=0xc7968732 > > path=\newdir > > mkdir-17942 [000] .... 447446.808233: > > smb3_query_info_compound_err: xid=8 sid=0x7dc5fd6f tid=0xc7968732 > > rc=-2 > > mkdir-17942 [000] .... 447446.808251: smb3_mkdir_enter: > > xid=9 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir > > mkdir-17942 [000] .... 447446.809161: smb3_mkdir_done: > > xid=9 sid=0x7dc5fd6f tid=0xc7968732 > > mkdir-17942 [000] .... 447446.809178: > > smb3_query_info_compound_enter: xid=9 sid=0x7dc5fd6f tid=0xc7968732 > > path=\newdir > > mkdir-17942 [000] .... 447446.809979: > > smb3_query_info_compound_done: xid=9 sid=0x7dc5fd6f tid=0xc7968732 > > rmdir-17943 [001] .... 447451.374029: > > smb3_query_info_compound_enter: xid=10 sid=0x7dc5fd6f tid=0xc7968732 > > path=\baddir > > rmdir-17943 [001] .... 447451.379621: > > smb3_query_info_compound_err: xid=10 sid=0x7dc5fd6f tid=0xc7968732 > > rc=-2 > > rmdir-17944 [001] .... 447456.088795: > > smb3_query_info_compound_enter: xid=11 sid=0x7dc5fd6f tid=0xc7968732 > > path=\newdir > > rmdir-17944 [001] .... 447456.089615: > > smb3_query_info_compound_done: xid=11 sid=0x7dc5fd6f tid=0xc7968732 > > rmdir-17944 [001] .... 447456.089640: smb3_rmdir_enter: > > xid=12 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir > > rmdir-17944 [001] .... 447456.090651: smb3_rmdir_done: > > xid=12 sid=0x7dc5fd6f tid=0xc7968732 > > touch-17945 [006] .... 447460.575789: > > smb3_set_info_compound_enter: xid=14 sid=0x7dc5fd6f tid=0xc7968732 > > path=\file > > touch-17945 [006] .... 447460.576571: > > smb3_set_info_compound_done: xid=14 sid=0x7dc5fd6f tid=0xc7968732 > > ln-17946 [001] .... 447468.254480: > > smb3_query_info_compound_enter: xid=16 sid=0x7dc5fd6f tid=0xc7968732 > > path=\linkedfile > > ln-17946 [001] .... 447468.255082: > > smb3_query_info_compound_err: xid=16 sid=0x7dc5fd6f tid=0xc7968732 > > rc=-2 > > ln-17946 [001] .... 447468.255118: > > smb3_query_info_compound_enter: xid=17 sid=0x7dc5fd6f tid=0xc7968732 > > path=\file > > ln-17946 [001] .... 447468.255715: > > smb3_query_info_compound_done: xid=17 sid=0x7dc5fd6f tid=0xc7968732 > > ln-17946 [001] .... 447468.255760: > > smb3_query_info_compound_enter: xid=18 sid=0x7dc5fd6f tid=0xc7968732 > > path=\linkedfile > > ln-17946 [001] .... 447468.256254: > > smb3_query_info_compound_err: xid=18 sid=0x7dc5fd6f tid=0xc7968732 > > rc=-2 > > ln-17946 [001] .... 447468.256277: smb3_hardlink_enter: > > xid=19 sid=0x7dc5fd6f tid=0xc7968732 path=\file > > ln-17946 [001] .... 447468.256954: smb3_hardlink_done: > > xid=19 sid=0x7dc5fd6f tid=0xc7968732 > > gmain-2225 [004] .... 447468.257130: > > smb3_query_info_compound_enter: xid=20 sid=0x7dc5fd6f tid=0xc7968732 > > path=\linkedfile > > gmain-2225 [005] .... 447468.257788: > > smb3_query_info_compound_done: xid=20 sid=0x7dc5fd6f tid=0xc7968732 > > > > On Tue, Mar 12, 2019 at 4:51 PM Pavel Shilovsky <piastryyy@gmail.com> wrote: > > > > > > I actually like the idea proposed in the patch: this way we will be > > > able to track logical operations better. In a case we need a deeper > > > logging we already have mid traces which contains MID, TID, SID and > > > CMD - everything you need to trace individual SMB packet regardless of > > > whether it is a part of compounding chain or not. > > > > > > Now in order to match both logical operation and SMB packets traces we > > > need something common - like XID. Currently we do not propagate XID > > > down to the transport layer, let's do that - this way we can trace > > > individual system call from the very beginning to the completeness on > > > every layer inside cifs.ko. > > > > > > вт, 12 мар. 2019 г. в 00:19, Steve French <smfrench@gmail.com>: > > > > > > > > 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@gmail.com> 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() > > > > > > > > > > > As pointed above we already have a similar tracing inside > > > compound_send_recv and other transport layer functions - command level > > > tracing. The only problem is that we do not log failure cases when we > > > didn't send the packet - we only log server responses in > > > map_smb2_to_linux_error. This is another area of the tracing where a > > > fix is needed. > > > > > > -- > > > Best regards, > > > Pavel Shilovsky > > > > > > > > -- > > Thanks, > > > > Steve
From ab7dbfbefe06f51b0fe9a5edbdab93469bc896f1 Mon Sep 17 00:00:00 2001 From: Steve French <stfrench@microsoft.com> Date: Mon, 11 Mar 2019 16:20:17 -0500 Subject: [PATCH] [smb3] Add dynamic trace points for various compounded smb3 ops Adds trace points for enter and exit (done vs. error) for: compounded query and setinfo, hardlink, rename, mkdir, rmdir, set_eof, delete (unlink) Signed-off-by: Steve French <stfrench@microsoft.com> --- fs/cifs/smb2inode.c | 71 ++++++++++++++++++++++++++++++++++++--- fs/cifs/trace.h | 82 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 148 insertions(+), 5 deletions(-) diff --git a/fs/cifs/smb2inode.c b/fs/cifs/smb2inode.c index 01a76bccdb8d..f3deb59625c0 100644 --- a/fs/cifs/smb2inode.c +++ b/fs/cifs/smb2inode.c @@ -37,6 +37,16 @@ #include "smb2pdu.h" #include "smb2proto.h" +static void +free_set_inf_compound(struct smb_rqst *rqst) +{ + if (rqst[1].rq_iov) + SMB2_set_info_free(&rqst[1]); + if (rqst[2].rq_iov) + SMB2_close_free(&rqst[2]); +} + + static int smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, struct cifs_sb_info *cifs_sb, const char *full_path, @@ -104,7 +114,6 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, memset(&qi_iov, 0, sizeof(qi_iov)); rqst[num_rqst].rq_iov = qi_iov; rqst[num_rqst].rq_nvec = 1; - rc = SMB2_query_info_init(tcon, &rqst[num_rqst], COMPOUND_FID, COMPOUND_FID, FILE_ALL_INFORMATION, SMB2_O_INFO_FILE, 0, @@ -112,14 +121,17 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, PATH_MAX * 2, 0, NULL); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_query_info_compound_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_DELETE: + trace_smb3_delete_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_MKDIR: /* * Directories are created through parameters in the * SMB2_open() call. */ + trace_smb3_mkdir_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_RMDIR: memset(&si_iov, 0, sizeof(si_iov)); @@ -135,6 +147,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_O_INFO_FILE, 0, data, size); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_rmdir_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_SET_EOF: memset(&si_iov, 0, sizeof(si_iov)); @@ -150,6 +163,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_O_INFO_FILE, 0, data, size); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_set_eof_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_SET_INFO: memset(&si_iov, 0, sizeof(si_iov)); @@ -166,6 +180,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_O_INFO_FILE, 0, data, size); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_set_info_compound_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_RENAME: memset(&si_iov, 0, sizeof(si_iov)); @@ -190,6 +205,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_O_INFO_FILE, 0, data, size); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_rename_enter(xid, ses->Suid, tcon->tid); break; case SMB2_OP_HARDLINK: memset(&si_iov, 0, sizeof(si_iov)); @@ -214,6 +230,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_O_INFO_FILE, 0, data, size); smb2_set_next_command(tcon, &rqst[num_rqst]); smb2_set_related(&rqst[num_rqst++]); + trace_smb3_hardlink_enter(xid, ses->Suid, tcon->tid); break; default: cifs_dbg(VFS, "Invalid command\n"); @@ -252,21 +269,65 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, SMB2_query_info_free(&rqst[1]); if (rqst[2].rq_iov) SMB2_close_free(&rqst[2]); + if (rc) + trace_smb3_query_info_compound_err(xid, ses->Suid, + tcon->tid, rc); + else + trace_smb3_query_info_compound_done(xid, ses->Suid, + tcon->tid); break; case SMB2_OP_DELETE: + if (rc) + trace_smb3_delete_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_delete_done(xid, ses->Suid, tcon->tid); + if (rqst[1].rq_iov) + SMB2_close_free(&rqst[1]); + break; case SMB2_OP_MKDIR: + if (rc) + trace_smb3_mkdir_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_mkdir_done(xid, ses->Suid, tcon->tid); if (rqst[1].rq_iov) SMB2_close_free(&rqst[1]); break; case SMB2_OP_HARDLINK: + if (rc) + trace_smb3_hardlink_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_hardlink_done(xid, ses->Suid, tcon->tid); + free_set_inf_compound(rqst); + break; case SMB2_OP_RENAME: + if (rc) + trace_smb3_rename_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_rename_done(xid, ses->Suid, tcon->tid); + free_set_inf_compound(rqst); + break; case SMB2_OP_RMDIR: + if (rc) + trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid); + free_set_inf_compound(rqst); + break; case SMB2_OP_SET_EOF: + if (rc) + trace_smb3_set_eof_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_set_eof_done(xid, ses->Suid, tcon->tid); + free_set_inf_compound(rqst); + break; case SMB2_OP_SET_INFO: - if (rqst[1].rq_iov) - SMB2_set_info_free(&rqst[1]); - if (rqst[2].rq_iov) - SMB2_close_free(&rqst[2]); + if (rc) + trace_smb3_set_info_compound_err(xid, ses->Suid, + tcon->tid, rc); + else + trace_smb3_set_info_compound_done(xid, ses->Suid, + tcon->tid); + free_set_inf_compound(rqst); break; } free_rsp_buf(resp_buftype[0], rsp_iov[0].iov_base); diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index c78e96c4cc53..0455fc7e5235 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -242,6 +242,88 @@ DEFINE_SMB3_INF_ERR_EVENT(query_info_err); DEFINE_SMB3_INF_ERR_EVENT(set_info_err); DEFINE_SMB3_INF_ERR_EVENT(fsctl_err); +DECLARE_EVENT_CLASS(smb3_inf_compound_enter_class, + TP_PROTO(unsigned int xid, + __u32 tid, + __u64 sesid), + TP_ARGS(xid, tid, sesid), + TP_STRUCT__entry( + __field(unsigned int, xid) + __field(__u32, tid) + __field(__u64, sesid) + ), + TP_fast_assign( + __entry->xid = xid; + __entry->tid = tid; + __entry->sesid = sesid; + ), + TP_printk("xid=%u sid=0x%llx tid=0x%x", + __entry->xid, __entry->sesid, __entry->tid) +) + +#define DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(name) \ +DEFINE_EVENT(smb3_inf_compound_enter_class, smb3_##name, \ + TP_PROTO(unsigned int xid, \ + __u32 tid, \ + __u64 sesid), \ + TP_ARGS(xid, tid, sesid)) + +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_done); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_enter); +DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_done); + +DECLARE_EVENT_CLASS(smb3_inf_compound_err_class, + TP_PROTO(unsigned int xid, + __u32 tid, + __u64 sesid, + int rc), + TP_ARGS(xid, tid, sesid, rc), + TP_STRUCT__entry( + __field(unsigned int, xid) + __field(__u32, tid) + __field(__u64, sesid) + __field(int, rc) + ), + TP_fast_assign( + __entry->xid = xid; + __entry->tid = tid; + __entry->sesid = sesid; + __entry->rc = rc; + ), + TP_printk("xid=%u sid=0x%llx tid=0x%x rc=%d", + __entry->xid, __entry->sesid, __entry->tid, __entry->rc) +) + +#define DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(name) \ +DEFINE_EVENT(smb3_inf_compound_err_class, smb3_##name, \ + TP_PROTO(unsigned int xid, \ + __u32 tid, \ + __u64 sesid, \ + int rc), \ + TP_ARGS(xid, tid, sesid, rc)) + +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(query_info_compound_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(hardlink_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rename_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rmdir_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_eof_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_info_compound_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(mkdir_err); +DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(delete_err); + /* * For logging SMB3 Status code and Command for responses which return errors */ -- 2.17.1
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