SMB2 performance is worse than SMB1 while iometer 512byte transfer
Jones
jones.kstw at gmail.com
Sat Sep 14 23:40:02 CEST 2013
Hi Jeremy,
Thanks for kindly feedback!
I'm very puzzled by you seeing vfprintf
> in the SMB2 traces. What debug level have
> you set in your smb.conf ?
>
" debug level" and "log level" is not explicit specified in smb.conf,
so this might be the default value,
to make sure this with GDB,
(gdb) p Globals.szLogLevel
$1 = 0x8992f10 "1"
(gdb) p /d TEVENT_DEBUG_TRACE
$2 = 3
(gdb)
These tevent_debug() calls inside
> tevent_common_loop_immediate() and
> tevent_common_schedule_immediate() are
> being done at a level of TEVENT_DEBUG_TRACE.
>
> Inside lib/util/tevent_debug.c we have:
>
> samba_tevent_debug()
>
> where TEVENT_DEBUG_TRACE is mapped to
> a samba_level = 50.
>
> You should only be seeing vfprintf
> calls coming from tevent_common_loop_immediate()
> and tevent_common_schedule_immediate()
> if your debug level is set to 50 or greater.
>
> Can you do some digging to understand
> where these vfprintf are being called from ?
>
>
Yes, found the call stacks with "perf top -G -p <smbd_pid>",
it shows vfprintf is came from tevent_common_schedule_immediate() and
tevent_common_loop_immediate(),
perf top -G -p <smbd_pid>:
5.34% libc-2.6.1.so [.] vfprintf
|
--- vfprintf
_IO_vasprintf
s3_event_debug
tevent_debug
|
|--69.75%-- tevent_common_schedule_immediate
| _tevent_schedule_immediate
| tevent_req_post
| |
| |--52.13%-- smbd_smb2_request_process_read
| | .L437
| | smbd_smb2_request_incoming
| | _tevent_req_notify_callback
| | tevent_req_finish
| | _tevent_req_done
| | smbd_smb2_request_read_done
| | _tevent_req_notify_callback
| | tevent_req_finish
| | _tevent_req_done
| | tstream_readv_pdu_queue_done
| | _tevent_req_notify_callback
| | tevent_req_finish
| | _tevent_req_done
| | tstream_readv_pdu_ask_for_next_vector
| | tstream_readv_pdu_readv_done
| | _tevent_req_notify_callback
| | tevent_req_finish
| | _tevent_req_done
| | tstream_readv_done
| | _tevent_req_notify_callback
| | tevent_req_finish
| | tevent_req_trigger
| | tevent_common_loop_immediate
| | run_events_poll
| | smbd_process
| | smbd_accept_connection
| | run_events_poll
| | s3_event_loop_once
| | _tevent_loop_once
| | main
| | __libc_start_main
| | _start
| |
| --47.87%-- tstream_bsd_readv_send
| tstream_readv_send
| tstream_readv_pdu_ask_for_next_vector
| tstream_readv_pdu_readv_done
| _tevent_req_notify_callback
| tevent_req_finish
| _tevent_req_done
| tstream_readv_done
| _tevent_req_notify_callback
| tevent_req_finish
| _tevent_req_done
| tstream_bsd_readv_handler
| tstream_bsd_fde_handler
| run_events_poll
| smbd_process
| smbd_accept_connection
| run_events_poll
| s3_event_loop_once
| _tevent_loop_once
| main
| __libc_start_main
| _start
|
|--44.54%-- tevent_common_loop_immediate
| run_events_poll
| smbd_process
| smbd_accept_connection
| run_events_poll
| s3_event_loop_once
| _tevent_loop_once
| main
| __libc_start_main
| _start
--82779907281386.88%-- [...]
To make sure this with GDB,
set the breakpoint to vfprintf and dump backtrace,
Breakpoint 1, 0xf79f6500 in vfprintf () from /lib/libc.so.6
#0 0xf79f6500 in vfprintf () from /lib/libc.so.6
#1 0xf7a1920c in vasprintf () from /lib/libc.so.6
#2 0x0846b0c3 in s3_event_debug (context=0x0, level=TEVENT_DEBUG_TRACE,
fmt=0xf7b275bc "Schedule immediate event \"%s\": %p\n", ap=0xffffd05c
"\306y\262\367\070\031\233\b\270\256\200\b\210\320\377\377\364\217\262\367\310\030\233\b\310\030\233\b\230\320\377\377$$\262\367\070\031\233\b\260\032\231\b\310H\262\367\310\030\233\b\306y\262\367\064y\262\367\310\320\377\377\240I\262\367\070\031\233\b\260\032\231\b\310H\262\367\310\030\233\b\306y\262\367\064y\262\367
") at lib/events.c:442
#3 0xf7b22e12 in tevent_debug (ev=0xf7b275bc, level=TEVENT_DEBUG_TRACE,
fmt=0xf7b275bc "Schedule immediate event \"%s\": %p\n") at
../lib/tevent/tevent_debug.c:93
#4 0xf7b23a79 in tevent_common_schedule_immediate (im=0x89b1938,
ev=0x8991ab0, handler=0xf7b248c8 <tevent_req_trigger>,
private_data=0x89b18c8, handler_name=0xf7b279c6 "tevent_req_trigger",
location=0xf7b27934 "../lib/tevent/tevent_req.c:163") at
../lib/tevent/tevent_immediate.c:95
#5 0xf7b22424 in _tevent_schedule_immediate (im=0x89b1938, ev=0x8991ab0,
handler=0xf7b248c8 <tevent_req_trigger>, private_data=0x89b18c8,
handler_name=0xf7b279c6 "tevent_req_trigger", location=0xf7b27934
"../lib/tevent/tevent_req.c:163") at ../lib/tevent/tevent.c:403
#6 0xf7b249a0 in tevent_req_post (req=0x89b18c8, ev=0x8991ab0) at
../lib/tevent/tevent_req.c:162
#7 0x0823a4d4 in tstream_bsd_writev_send (mem_ctx=0x89b1888, ev=0x8991ab0,
stream=0x89a4158, vector=0x89b1478, count=4) at
../lib/tsocket/tsocket_bsd.c:1859
#8 0x08236bc5 in tstream_writev_send (mem_ctx=0x89b1718, ev=0x8991ab0,
stream=0x89a4158, vector=0x89b1478, count=4) at ../lib/tsocket/tsocket.c:695
#9 0x08237be9 in tstream_writev_queue_trigger (req=0x89b1648,
private_data=0x0) at ../lib/tsocket/tsocket_helpers.c:502
#10 0xf7b24de5 in tevent_queue_immediate_trigger (ev=0x8991ab0,
im=0x89a0318, private_data=0x89a0f68) at ../lib/tevent/tevent_queue.c:144
#11 0xf7b2388d in tevent_common_loop_immediate (ev=0x8991ab0) at
../lib/tevent/tevent_immediate.c:139
#12 0x0846b3b5 in run_events_poll (ev=0x8991ab0, pollrtn=0, pfds=0x0,
num_pfds=0) at lib/events.c:197
#13 0x081724b0 in smbd_server_connection_loop_once (conn=<optimized out>)
at smbd/process.c:962
#14 smbd_process (sconn=0x8991b20) at smbd/process.c:3143
#15 0x08745d2c in smbd_accept_connection (ev=0x8991ab0, fde=0x89acff8,
flags=1, private_data=0x89abb98) at smbd/server.c:643
#16 0x0846b794 in run_events_poll (ev=0x8991ab0, pollrtn=1, pfds=0x89a5280,
num_pfds=3) at lib/events.c:286
#17 0x0846bbf4 in s3_event_loop_once (ev=0x8991ab0, location=0x89540fb
"smbd/server.c:1027") at lib/events.c:349
#18 0xf7b226cd in _tevent_loop_once (ev=0x8991ab0, location=0x89540fb
"smbd/server.c:1027") at ../lib/tevent/tevent.c:494
#19 0x08747b41 in smbd_parent_loop (parent=<optimized out>) at
smbd/server.c:1027
#20 main (argc=3, argv=0xffffda14) at smbd/server.c:1559
It is likely that samba4 series with CHECK_DEBUGLVL wrapped inside these
files,
samba-4.0.9/source3/lib/events.c
samba-4.1.0rc3/lib/util/tevent_debug.c
samba-master/lib/util/tevent_debug.c
Per this hint, finally found that in samba-3.6.18/source3/lib/events.c,
so wrapped vasprintf with CHECK_DEBUGLVL() inside s3_event_debug(),
then undo the comment in tevent_common_loop_immediate() and
event_common_schedule_immediate(),
now it looks like
if (CHECK_DEBUGLVL(samba_level)) {
if (vasprintf(&s, fmt, ap) == -1) {
return;
}
DEBUG(samba_level, ("s3_event: %s", s));
free(s);
}
After this modified the vfprintf do not show in perf any more,
Im not sure if anything required to change either to make vfprintf hidden.
Here is the list to show the difference,
Version | mapped samba_level | wrapped CHECK_DEBUGLVL | vfprinf shows
in perf
--------------------------------------------------------------
3.6.18 11 No Yes
4.0.9 11 Yes No
4.1.0rc3 50 Yes No
samba-master 50 Yes No
But still one thing interesting,
though no "debug level" or "log level" is specified in smb.conf,
Globals.szLogLevel = 1 made me confused.
Per this link depicted that default is 0,
http://www.samba.org/samba/docs/man/manpages-3/smb.conf.5.html
Regards,
Jones
More information about the samba-technical
mailing list