[SMB3] Add various dynamic tracepoints for compounded operations
diff mbox series

Message ID CAH2r5muY3xgVW03Mi8N-c4wyZFikzTeZgLDEuGLoXFXNZ-wFHA@mail.gmail.com
State New
Headers show
Series
  • [SMB3] Add various dynamic tracepoints for compounded operations
Related show

Commit Message

Steve French March 11, 2019, 9:25 p.m. UTC
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

Comments

Pavel Shilovsky March 11, 2019, 10:18 p.m. UTC | #1
пн, 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
Steve French March 11, 2019, 10:31 p.m. UTC | #2
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
Steve French March 12, 2019, 5:35 a.m. UTC | #3
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
ronnie sahlberg March 12, 2019, 6:06 a.m. UTC | #4
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
Steve French March 12, 2019, 7:18 a.m. UTC | #5
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
Pavel Shilovsky March 12, 2019, 9:51 p.m. UTC | #6
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
Steve French March 13, 2019, 5:03 a.m. UTC | #7
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
ronnie sahlberg March 13, 2019, 5:38 a.m. UTC | #8
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
Steve French March 13, 2019, 5:39 a.m. UTC | #9
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

Patch
diff mbox series

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