Re: samba4 slow startup, shared libs?
For reference: https://bugzilla.samba.org/show_bug.cgi?id=11355 Ian McWilliam From: Ian Mcwilliam Sent: Friday, 19 June 2015 10:03 AM To: Jérémie Courrèges-Anglas Cc: Stuart Henderson; Mark Kettenis; tech@openbsd.org Subject: RE: samba4 slow startup, shared libs? Sweet. I'll knockup a patch and send it upstream shortly. Ian McWilliam From: Jérémie Courrèges-Anglas [j...@wxcvbn.org] Sent: Thursday, 18 June 2015 8:11 PM To: Ian Mcwilliam Cc: Stuart Henderson; Mark Kettenis; tech@openbsd.org Subject: Re: samba4 slow startup, shared libs? Ian Mcwilliam i.mcwill...@uws.edu.au writes: Curiously from --- samba-4.0.3/wscript Tue Dec 4 21:07:44 2012 +++ samba-4.0.26/wscript Mon Dec 8 18:46:38 2014 -if sys.platform != openbsd4: +if not sys.platform.startswith(openbsd): conf.env.asneeded_ldflags = conf.ADD_LDFLAGS('-Wl,--as-needed', testflags=True) Here's the output of LD_DEBUG=1 time samba-tool: ritchie /usr/ports/net/samba4$ tail before after == before == doing dtors obj 0x76bdc238000 @0x76c004b0a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0x76bb7b3b000 @0x76bfbc6e740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0x76bb7b3b800 @0x76b8c3331b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0x76c1ede3400 @0x76bbadbc950: [/usr/lib/libc.so.79.0] doing dtors obj 0x76c1ede3000 @0x76c333c5a40: [/usr/lib/libutil.so.12.1] doing dtors obj 0x76bdc238800 @0x76c0159b340: [/usr/lib/libm.so.9.0] 251.92 real 251.96 user 0.19 sys doing dtors doing dtors obj 0xf0ae0f94c00 @0xf0b5ec96950: [/usr/lib/libc.so.79.0] == after == doing dtors obj 0xa6021425000 @0xa60bf833a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0xa6021425800 @0xa603fca0740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0xa6034d7e800 @0xa60c0c911b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0xa60a5bcf400 @0xa604a3e0950: [/usr/lib/libc.so.79.0] doing dtors obj 0xa60a5bcf000 @0xa60eb3eba40: [/usr/lib/libutil.so.12.1] doing dtors obj 0xa6021425400 @0xa610ba86340: [/usr/lib/libm.so.9.0] 1.49 real 1.24 user 0.22 sys doing dtors doing dtors obj 0x4e7a8e11c00 @0x4e767f81950: [/usr/lib/libc.so.79.0] (with wip samba-4.1.18) -- jca | PGP : 0x1524E7EE / 5135 92C1 AD36 5293 2BDF DDCC 0DFA 74AE 1524 E7EE
Re: samba4 slow startup, shared libs?
Sweet. I'll knockup a patch and send it upstream shortly. Ian McWilliam From: Jérémie Courrèges-Anglas [j...@wxcvbn.org] Sent: Thursday, 18 June 2015 8:11 PM To: Ian Mcwilliam Cc: Stuart Henderson; Mark Kettenis; tech@openbsd.org Subject: Re: samba4 slow startup, shared libs? Ian Mcwilliam i.mcwill...@uws.edu.au writes: Curiously from --- samba-4.0.3/wscript Tue Dec 4 21:07:44 2012 +++ samba-4.0.26/wscript Mon Dec 8 18:46:38 2014 -if sys.platform != openbsd4: +if not sys.platform.startswith(openbsd): conf.env.asneeded_ldflags = conf.ADD_LDFLAGS('-Wl,--as-needed', testflags=True) Here's the output of LD_DEBUG=1 time samba-tool: ritchie /usr/ports/net/samba4$ tail before after == before == doing dtors obj 0x76bdc238000 @0x76c004b0a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0x76bb7b3b000 @0x76bfbc6e740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0x76bb7b3b800 @0x76b8c3331b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0x76c1ede3400 @0x76bbadbc950: [/usr/lib/libc.so.79.0] doing dtors obj 0x76c1ede3000 @0x76c333c5a40: [/usr/lib/libutil.so.12.1] doing dtors obj 0x76bdc238800 @0x76c0159b340: [/usr/lib/libm.so.9.0] 251.92 real 251.96 user 0.19 sys doing dtors doing dtors obj 0xf0ae0f94c00 @0xf0b5ec96950: [/usr/lib/libc.so.79.0] == after == doing dtors obj 0xa6021425000 @0xa60bf833a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0xa6021425800 @0xa603fca0740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0xa6034d7e800 @0xa60c0c911b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0xa60a5bcf400 @0xa604a3e0950: [/usr/lib/libc.so.79.0] doing dtors obj 0xa60a5bcf000 @0xa60eb3eba40: [/usr/lib/libutil.so.12.1] doing dtors obj 0xa6021425400 @0xa610ba86340: [/usr/lib/libm.so.9.0] 1.49 real 1.24 user 0.22 sys doing dtors doing dtors obj 0x4e7a8e11c00 @0x4e767f81950: [/usr/lib/libc.so.79.0] (with wip samba-4.1.18) -- jca | PGP : 0x1524E7EE / 5135 92C1 AD36 5293 2BDF DDCC 0DFA 74AE 1524 E7EE
Re: samba4 slow startup, shared libs?
Ian Mcwilliam i.mcwill...@uws.edu.au writes: Curiously from --- samba-4.0.3/wscript Tue Dec 4 21:07:44 2012 +++ samba-4.0.26/wscript Mon Dec 8 18:46:38 2014 -if sys.platform != openbsd4: +if not sys.platform.startswith(openbsd): conf.env.asneeded_ldflags = conf.ADD_LDFLAGS('-Wl,--as-needed', testflags=True) Here's the output of LD_DEBUG=1 time samba-tool: ritchie /usr/ports/net/samba4$ tail before after == before == doing dtors obj 0x76bdc238000 @0x76c004b0a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0x76bb7b3b000 @0x76bfbc6e740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0x76bb7b3b800 @0x76b8c3331b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0x76c1ede3400 @0x76bbadbc950: [/usr/lib/libc.so.79.0] doing dtors obj 0x76c1ede3000 @0x76c333c5a40: [/usr/lib/libutil.so.12.1] doing dtors obj 0x76bdc238800 @0x76c0159b340: [/usr/lib/libm.so.9.0] 251.92 real 251.96 user 0.19 sys doing dtors doing dtors obj 0xf0ae0f94c00 @0xf0b5ec96950: [/usr/lib/libc.so.79.0] == after == doing dtors obj 0xa6021425000 @0xa60bf833a90: [/usr/local/lib/libiconv.so.6.0] doing dtors doing dtors obj 0xa6021425800 @0xa603fca0740: [/usr/local/lib/libpython2.7.so.0.0] doing dtors obj 0xa6034d7e800 @0xa60c0c911b0: [/usr/lib/libstdc++.so.57.0] doing dtors obj 0xa60a5bcf400 @0xa604a3e0950: [/usr/lib/libc.so.79.0] doing dtors obj 0xa60a5bcf000 @0xa60eb3eba40: [/usr/lib/libutil.so.12.1] doing dtors obj 0xa6021425400 @0xa610ba86340: [/usr/lib/libm.so.9.0] 1.49 real 1.24 user 0.22 sys doing dtors doing dtors obj 0x4e7a8e11c00 @0x4e767f81950: [/usr/lib/libc.so.79.0] (with wip samba-4.1.18) -- jca | PGP : 0x1524E7EE / 5135 92C1 AD36 5293 2BDF DDCC 0DFA 74AE 1524 E7EE
Re: samba4 slow startup, shared libs?
Curiously from --- samba-4.0.3/wscript Tue Dec 4 21:07:44 2012 +++ samba-4.0.26/wscriptMon Dec 8 18:46:38 2014 -if sys.platform != openbsd4: +if not sys.platform.startswith(openbsd): conf.env.asneeded_ldflags = conf.ADD_LDFLAGS('-Wl,--as-needed', testflags=True) --- samba-4.0.3/buildtools/wafadmin/Tools/config_c.py Tue Oct 2 18:24:39 2012 +++ samba-4.0.26/buildtools/wafadmin/Tools/config_c.py Wed May 28 03:20:37 2014 @@ -73,6 +73,19 @@ app('CCFLAGS_' + uselib, x) app('CXXFLAGS_' + uselib, x) app('LINKFLAGS_' + uselib, x) + # + # NOTE on special treatment of -Wl,-R and -Wl,-rpath: + # + # It is important to not put a library provided RPATH + # into the LINKFLAGS but in the RPATH instead, since + # the provided LINKFLAGS get prepended to our own internal + # RPATH later, and hence can potentially lead to linking + # in too old versions of our internal libs. + # + elif x.startswith('-Wl,-R'): + app('RPATH_' + uselib, x[6:]) + elif x.startswith('-Wl,-rpath,'): + app('RPATH_' + uselib, x[11:]) elif x.startswith('-Wl'): app('LINKFLAGS_' + uselib, x) elif x.startswith('-m') or x.startswith('-f'): There is also a bunch of PIE related changes too, I'll post if people think they may be relevant. Ian McWilliam From: owner-t...@openbsd.org [owner-t...@openbsd.org] on behalf of Stuart Henderson [st...@openbsd.org] Sent: Wednesday, 10 June 2015 9:48 PM To: Mark Kettenis Cc: tech@openbsd.org Subject: Re: samba4 slow startup, shared libs? On 2015/06/05 13:27, Mark Kettenis wrote: Date: Fri, 5 Jun 2015 11:15:38 +0100 From: Stuart Henderson st...@openbsd.org net/samba4 is in the ports tree but not currently enabled in the build, we're still only using samba 3.x for various reasons, but unfortunately samba 3 is getting decreasingly useful as more Windows setups move to newer versions. One of the issues is that startup of samba4 on OpenBSD is very slow indeed, seemingly before control is transferred to the program. From the LD_DEBUG output with timestamps (using the very handy ts(1) from moreutils): # LD_DEBUG=1 smbd -D 21 | ts %.s ..snip.. 1433498513.546306 examining: '/usr/local/lib/libhogweed.so.1.1' 1433498513.546323 loading: libnettle.so.1.2 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546339 loading: libgmp.so.9.0 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546354 linking dep /usr/local/lib/libnettle.so.1.2 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546370 linking dep /usr/local/lib/libgmp.so.9.0 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546386 examining: '/usr/local/lib/libgmp.so.9.0' 1433498584.125659 flags /usr/libexec/ld.so = 0x0 1433498584.125783 obj /usr/libexec/ld.so has smbd as head 1433498584.149165 relocation took 0.023504 1433498584.149215 StartEnd Type Open Ref GrpRef Name 1433498584.149249 04bec650 04bec691 exe 10 0 smbd 1433498584.149272 04c19b74e000 04c19bb6 rlib 0107 0 /usr/lib/libpthread.so.19.0 1433498584.149293 04c18f3df000 04c18f812000 rlib 075 0 /usr/local/lib/libsamba-util.so.0.0 ..snip.. - a 74 second delay after examining: '/usr/local/lib/libgmp.so.9.0'. Does anyone have suggestions for finding out what's going on here? Full text snipped from the above is at http://junkpile.org/samba4-lddebug.txt My first guess would have been that it is spending a lot of time on initial relocations. But the line: 1433498584.149165 relocation took 0.023504 pretty much rules that out. My suggestion would be to add a few more DL_DEB() statements inside of ld.so/loader.c:_dl_boot(), starting just after the _dl_load_dep_libs() call in that function and try to narrow it down. The part taking the biggest chunk of time is _dl_cache_grpsym_list() with its recursive calls (64 seconds). 1433936487.139917 _dl_cache_grpsym_list: 1433936551.414114 _dl_cache_grpsym_list:done ctors for libpthread are fairly slow too (35 seconds) but I think that's out of ld.so's hands. ... 1433936551.538493 _dl_debug_state done 1433936551.538508 doing ctors obj 0x138a43269400 @0x138a74fe0ca0: [/usr/lib/libpthread.so.19.0] 1433936587.157910 doing ctors obj 0x138ae5e30800 @0x138af0447f80: [/usr/local/lib/samba/libreplace.so.0.0] ...
Re: samba4 slow startup, shared libs?
On 2015/06/05 13:27, Mark Kettenis wrote: Date: Fri, 5 Jun 2015 11:15:38 +0100 From: Stuart Henderson st...@openbsd.org net/samba4 is in the ports tree but not currently enabled in the build, we're still only using samba 3.x for various reasons, but unfortunately samba 3 is getting decreasingly useful as more Windows setups move to newer versions. One of the issues is that startup of samba4 on OpenBSD is very slow indeed, seemingly before control is transferred to the program. From the LD_DEBUG output with timestamps (using the very handy ts(1) from moreutils): # LD_DEBUG=1 smbd -D 21 | ts %.s ..snip.. 1433498513.546306 examining: '/usr/local/lib/libhogweed.so.1.1' 1433498513.546323 loading: libnettle.so.1.2 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546339 loading: libgmp.so.9.0 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546354 linking dep /usr/local/lib/libnettle.so.1.2 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546370 linking dep /usr/local/lib/libgmp.so.9.0 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546386 examining: '/usr/local/lib/libgmp.so.9.0' 1433498584.125659 flags /usr/libexec/ld.so = 0x0 1433498584.125783 obj /usr/libexec/ld.so has smbd as head 1433498584.149165 relocation took 0.023504 1433498584.149215 StartEnd Type Open Ref GrpRef Name 1433498584.149249 04bec650 04bec691 exe 10 0 smbd 1433498584.149272 04c19b74e000 04c19bb6 rlib 0107 0 /usr/lib/libpthread.so.19.0 1433498584.149293 04c18f3df000 04c18f812000 rlib 075 0 /usr/local/lib/libsamba-util.so.0.0 ..snip.. - a 74 second delay after examining: '/usr/local/lib/libgmp.so.9.0'. Does anyone have suggestions for finding out what's going on here? Full text snipped from the above is at http://junkpile.org/samba4-lddebug.txt My first guess would have been that it is spending a lot of time on initial relocations. But the line: 1433498584.149165 relocation took 0.023504 pretty much rules that out. My suggestion would be to add a few more DL_DEB() statements inside of ld.so/loader.c:_dl_boot(), starting just after the _dl_load_dep_libs() call in that function and try to narrow it down. The part taking the biggest chunk of time is _dl_cache_grpsym_list() with its recursive calls (64 seconds). 1433936487.139917 _dl_cache_grpsym_list: 1433936551.414114 _dl_cache_grpsym_list:done ctors for libpthread are fairly slow too (35 seconds) but I think that's out of ld.so's hands. ... 1433936551.538493 _dl_debug_state done 1433936551.538508 doing ctors obj 0x138a43269400 @0x138a74fe0ca0: [/usr/lib/libpthread.so.19.0] 1433936587.157910 doing ctors obj 0x138ae5e30800 @0x138af0447f80: [/usr/local/lib/samba/libreplace.so.0.0] ...
samba4 slow startup, shared libs?
net/samba4 is in the ports tree but not currently enabled in the build, we're still only using samba 3.x for various reasons, but unfortunately samba 3 is getting decreasingly useful as more Windows setups move to newer versions. One of the issues is that startup of samba4 on OpenBSD is very slow indeed, seemingly before control is transferred to the program. From the LD_DEBUG output with timestamps (using the very handy ts(1) from moreutils): # LD_DEBUG=1 smbd -D 21 | ts %.s ..snip.. 1433498513.546306 examining: '/usr/local/lib/libhogweed.so.1.1' 1433498513.546323 loading: libnettle.so.1.2 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546339 loading: libgmp.so.9.0 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546354 linking dep /usr/local/lib/libnettle.so.1.2 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546370 linking dep /usr/local/lib/libgmp.so.9.0 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546386 examining: '/usr/local/lib/libgmp.so.9.0' 1433498584.125659 flags /usr/libexec/ld.so = 0x0 1433498584.125783 obj /usr/libexec/ld.so has smbd as head 1433498584.149165 relocation took 0.023504 1433498584.149215 StartEnd Type Open Ref GrpRef Name 1433498584.149249 04bec650 04bec691 exe 10 0 smbd 1433498584.149272 04c19b74e000 04c19bb6 rlib 0107 0 /usr/lib/libpthread.so.19.0 1433498584.149293 04c18f3df000 04c18f812000 rlib 075 0 /usr/local/lib/libsamba-util.so.0.0 ..snip.. - a 74 second delay after examining: '/usr/local/lib/libgmp.so.9.0'. Does anyone have suggestions for finding out what's going on here? Full text snipped from the above is at http://junkpile.org/samba4-lddebug.txt The simpler programs in samba4 are also slower than expected to startup (smbclient --version takes 3-4 seconds) but I haven't identified others which are quite as bad as smbd yet.
Re: samba4 slow startup, shared libs?
Date: Fri, 5 Jun 2015 11:15:38 +0100 From: Stuart Henderson st...@openbsd.org net/samba4 is in the ports tree but not currently enabled in the build, we're still only using samba 3.x for various reasons, but unfortunately samba 3 is getting decreasingly useful as more Windows setups move to newer versions. One of the issues is that startup of samba4 on OpenBSD is very slow indeed, seemingly before control is transferred to the program. From the LD_DEBUG output with timestamps (using the very handy ts(1) from moreutils): # LD_DEBUG=1 smbd -D 21 | ts %.s ..snip.. 1433498513.546306 examining: '/usr/local/lib/libhogweed.so.1.1' 1433498513.546323 loading: libnettle.so.1.2 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546339 loading: libgmp.so.9.0 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546354 linking dep /usr/local/lib/libnettle.so.1.2 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546370 linking dep /usr/local/lib/libgmp.so.9.0 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546386 examining: '/usr/local/lib/libgmp.so.9.0' 1433498584.125659 flags /usr/libexec/ld.so = 0x0 1433498584.125783 obj /usr/libexec/ld.so has smbd as head 1433498584.149165 relocation took 0.023504 1433498584.149215 StartEnd Type Open Ref GrpRef Name 1433498584.149249 04bec650 04bec691 exe 10 0 smbd 1433498584.149272 04c19b74e000 04c19bb6 rlib 0107 0 /usr/lib/libpthread.so.19.0 1433498584.149293 04c18f3df000 04c18f812000 rlib 075 0 /usr/local/lib/libsamba-util.so.0.0 ..snip.. - a 74 second delay after examining: '/usr/local/lib/libgmp.so.9.0'. Does anyone have suggestions for finding out what's going on here? Full text snipped from the above is at http://junkpile.org/samba4-lddebug.txt My first guess would have been that it is spending a lot of time on initial relocations. But the line: 1433498584.149165 relocation took 0.023504 pretty much rules that out. My suggestion would be to add a few more DL_DEB() statements inside of ld.so/loader.c:_dl_boot(), starting just after the _dl_load_dep_libs() call in that function and try to narrow it down.
Re: samba4 slow startup, shared libs?
On Fri, June 5, 2015 14:27, Mark Kettenis wrote: Date: Fri, 5 Jun 2015 11:15:38 +0100 From: Stuart Henderson st...@openbsd.org net/samba4 is in the ports tree but not currently enabled in the build, we're still only using samba 3.x for various reasons, but unfortunately samba 3 is getting decreasingly useful as more Windows setups move to newer versions. One of the issues is that startup of samba4 on OpenBSD is very slow indeed, seemingly before control is transferred to the program. From the LD_DEBUG output with timestamps (using the very handy ts(1) from moreutils): # LD_DEBUG=1 smbd -D 21 | ts %.s ..snip.. 1433498513.546306 examining: '/usr/local/lib/libhogweed.so.1.1' 1433498513.546323 loading: libnettle.so.1.2 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546339 loading: libgmp.so.9.0 required by /usr/local/lib/libhogweed.so.1.1 1433498513.546354 linking dep /usr/local/lib/libnettle.so.1.2 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546370 linking dep /usr/local/lib/libgmp.so.9.0 as child of /usr/local/lib/libhogweed.so.1.1 1433498513.546386 examining: '/usr/local/lib/libgmp.so.9.0' 1433498584.125659 flags /usr/libexec/ld.so = 0x0 1433498584.125783 obj /usr/libexec/ld.so has smbd as head 1433498584.149165 relocation took 0.023504 1433498584.149215 StartEnd Type Open Ref GrpRef Name 1433498584.149249 04bec650 04bec691 exe 10 0 smbd 1433498584.149272 04c19b74e000 04c19bb6 rlib 0107 0 /usr/lib/libpthread.so.19.0 1433498584.149293 04c18f3df000 04c18f812000 rlib 075 0 /usr/local/lib/libsamba-util.so.0.0 ..snip.. - a 74 second delay after examining: '/usr/local/lib/libgmp.so.9.0'. Does anyone have suggestions for finding out what's going on here? Full text snipped from the above is at http://junkpile.org/samba4-lddebug.txt My first guess would have been that it is spending a lot of time on initial relocations. But the line: 1433498584.149165 relocation took 0.023504 pretty much rules that out. My suggestion would be to add a few more DL_DEB() statements inside of ld.so/loader.c:_dl_boot(), starting just after the _dl_load_dep_libs() call in that function and try to narrow it down. Vadim made an attempt to improve things. May be this can share some light. http://marc.info/?l=openbsd-portsm=140051145330799w=2 http://marc.info/?l=openbsd-portsm=140078438824316w=2 I've searched old mails and found that 4.0.3 was starting with normal speed. I have ldd output for 4.0.3 and 4.0.17 to compare.