Jan Koop
2014-Sep-24 14:27 UTC
[Samba] High CPU Load samba 4.1.12 possibly because of Notify Request problem
Hi List, I recently upgraded one of our high-volume SMB servers from samba 3.x to samba 4.1.12 (also changing the OS). Now I have a strange problem. The CPU load on the server is very high, processes that are causing it are nslcd or since I changed to it sssd and the smbd processes themselves. ? Top looks like this: --------------------------------- PID USER????? PR? NI? VIRT? RES? SHR S %CPU %MEM??? TIME+? COMMAND 2216 root????? 20?? 0? 200m 5820 3024 R 31.2? 0.1? 44:47.46 sssd_nss 3631 XXXXX? 20?? 0? 430m? 10m 8472 R 17.3? 0.3? 12:37.12 smbd 2870 XXXXX? 20?? 0? 434m? 17m? 11m R 16.3? 0.5? 21:22.22 smbd 3603 XXXXX? 20?? 0? 430m 9.8m 7492 R 16.3? 0.3? 14:19.45 smbd 3250 XXXXX? 20?? 0? 432m? 14m 9384 R 15.9? 0.4? 12:17.09 smbd 3616 XXXXX? 20?? 0? 430m? 11m 8452 R 15.9? 0.3? 13:37.91 smbd 2842 XXXXX? 20?? 0? 435m? 21m? 13m R 15.6? 0.6? 22:24.76 smbd 3246 XXXXX? 20?? 0? 430m? 12m 9684 S 15.6? 0.3? 15:35.65 smbd 3267 XXXXX? 20?? 0? 433m? 16m? 11m S 15.6? 0.4? 15:04.27 smbd 1637 XXXXX? 20?? 0? 425m? 15m? 13m S 14.9? 0.4? 13:32.95 smbd 2879 XXXXX? 20?? 0? 435m? 18m? 10m R 14.9? 0.5? 19:01.03 smbd 2899 XXXXX? 20?? 0 ?434m? 17m? 11m R 14.9? 0.5? 17:24.44 smbd 2838 XXXXX? 20?? 0? 433m? 17m? 11m R 14.3? 0.5? 11:46.12 smbd 1657 XXXXX? 20?? 0? 429m? 19m? 12m R 13.9? 0.5? 15:17.44 smbd 2841 XXXXX? 20?? 0? 434m? 17m? 10m R 13.9? 0.5? 14:31.61 smbd 2221 XXXXX? 20?? 0? 429m? 15m 9972 R 13.6? 0.4? 14:51.52 smbd 2495 XXXXX? 20?? 0? 425m? 12m 9.8m R 13.6? 0.3? 12:17.84 smbd 2837 XXXXX? 20?? 0? 434m? 20m? 13m R 13.6? 0.5? 17:46.70 smbd 2869 XXXXX? 20?? 0? 432m? 12m 7920 R 13.6? 0.3? 19:38.08 smbd 3605 XXXXX? 20?? 0? 433m? 15m 9.9m R 13.6? 0.4? 11:32.85 smbd 2277 XXXXX??? 20?? 0? 429m? 13m? 10m R 13.3? 0.4?? 2:53.38 smbd 2872 XXXXX?? 20?? 0? 434m? 17m? 10m R 13.3? 0.5? 18:19.79 smbd 2215 root????? 20?? 0? 212m 4900 3756 R 11.0? 0.1? 16:57.29 sssd_be 2340 root????? 20?? 0? 435m? 22m? 13m R? 4.0? 0.6?? 6:42.97 smbd 2377 root????? 20?? 0? 436m? 20m? 11m R? 4.0? 0.5?? 4:11.66 smbd ? ? --------------------------------- ? ? When I tshark the network traffic I always see these packets: --------------------------------- Seconds?? packet type 1.507312 SMB2 258 Create Request File: a\directory 1.508001 SMB2 242 Create Response File: a\directory 1.509120 SMB2 154 Notify Request File: a\directory 1.509786 SMB2 131 Notify Response, Error: STATUS_INVALID_PARAMETER 1.510548 SMB2 258 Create Request File: a\directory <starting over and over and over> --------------------------------- ? ? A debug level of 10 on such an smbd gives me: --------------------------------- [2014/09/24 16:15:04.429169, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:874(smb2_set_operation_credit)? smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/3287320/31 [2014/09/24 16:15:04.433078, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:3257(smbd_smb2_io_handler)? smbd_smb2_request idx[1] of 5 vectors [2014/09/24 16:15:04.433153, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:621(smb2_validate_sequence_number)? smb2_validate_sequence_number: clearing id 3287320 (position 2328) from bitmap [2014/09/24 16:15:04.433242, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:1878(smbd_smb2_request_dispatch)? smbd_smb2_request_dispatch: opcode[SMB2_OP_NOTIFY] mid = 3287320 [2014/09/24 16:15:04.433285,? 4, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/uid.c:384(change_to_user)? Skipping user change - already user [2014/09/24 16:15:04.433325, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:1780(smbd_smb2_request_verify_creditcharge)? mid 3287320, CreditCharge: 1, NeededCharge: 2 [2014/09/24 16:15:04.433393,? 2, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:1784(smbd_smb2_request_verify_creditcharge)? CreditCharge too low, given 1, needed 2 [2014/09/24 16:15:04.433435, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:2598(smbd_smb2_request_error_ex)? smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_INVALID_PARAMETER] || at ../source3/smbd/smb2_notify.c:85 [2014/09/24 16:15:04.433471, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:2499(smbd_smb2_request_done_ex)? smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_INVALID_PARAMETER] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:2651 [2014/09/24 16:15:04.433516, 10, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:874(smb2_set_operation_credit)? smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/3287321/31 --------------------------------- ? -The clients are Windows 7 pro x64 -Server Centos 6.5 / Samba 4.1.12 / -Domain member to a samba 3.x domain -Users in openLDAP RFC2307 directory ? -Global config section and relevant share: --------------------------------- [global] ?? workgroup = XXXX ?? security = domain ?? idmap config * : range = 16777216-33554431 ?? template shell = /sbin/nologin ?? winbind use default domain = false ?? winbind offline logon = false ??????? server string = %h SERVER Samba %v ??????? map untrusted to domain = yes ??????? encrypt passwords = Yes ??????? map to guest = Bad Password ??????? passwd program = /usr/bin/passwd %u ??? ????log level = 0 ??????? log file = /var/log/samba/log.smb.%m ??????? max log size = 1000 ??????? unix charset = UTF8 ??????? os level = 2 ??????? preferred master = No ??????? dns proxy = No ??????? wins server = 192.168.X.X ??????? preload = backup ??????? interfaces = 192.168.X.X/xx ? [X] ?????? comment = xxxxxx ??????? path = /xxx/x ??????? writeable = yes ??????? create mask = 0775 ??????? directory mask = 0775 ??????? veto files = /*.vlx/autorun.inf/*.fas/*.lsp/*.dvb/ ??????? invalid users = @xxx @xxx xxx xxx ??????? vfs objects = full_audit ??????? full_audit:prefix = %u|%I|%m|%S ??????? full_audit:success = unlink rmdir rename ??????? full_audit:failure = none ??????? full_audit:facility = local6 ??????? full_audit:priority = NOTICE --------------------------------- ? ? Help help, anyone? I don?t want to down-grade to samba 3.x Cheers, Jan ? ?
Jeremy Allison
2014-Sep-24 19:44 UTC
[Samba] High CPU Load samba 4.1.12 possibly because of Notify Request problem
On Wed, Sep 24, 2014 at 04:27:42PM +0200, Jan Koop wrote:> Hi List, > > I recently upgraded one of our high-volume SMB servers from samba 3.x to samba 4.1.12 (also changing the OS). > > Now I have a strange problem. > > The CPU load on the server is very high, processes that are causing it are nslcd or since I changed to it sssd and the smbd processes themselves.This is the root of the problem: [2014/09/24 16:15:04.433393,? 2, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:1784(smbd_smb2_request_v +erify_creditcharge)? CreditCharge too low, given 1, needed 2 Can you log a bug with the samba bugzilla and also upload a wireshark trace of these packets ? We'll need that to investigate & fix. Thanks ! Jeremy.
Jan Koop
2014-Sep-25 11:05 UTC
[Samba] High CPU Load samba 4.1.12 possibly because of Notify Request problem
Hi Jeremy, thanks for the reply. I filed a bug (#10839) https://bugzilla.samba.org/show_bug.cgi?id=10839 . One thing I forgot to state is that apparently this behavior occurs as soon as our users start AutoCAD 2011, don't know if this is relevant. Cheers, Jan -----Urspr?ngliche Nachricht----- Von: Jeremy Allison [mailto:jra at samba.org] Gesendet: Mittwoch, 24. September 2014 21:44 An: Jan Koop Cc: samba at lists.samba.org Betreff: Re: [Samba] High CPU Load samba 4.1.12 possibly because of Notify Request problem On Wed, Sep 24, 2014 at 04:27:42PM +0200, Jan Koop wrote:> Hi List, > > I recently upgraded one of our high-volume SMB servers from samba 3.x to samba 4.1.12 (also changing the OS). > > Now I have a strange problem. > > The CPU load on the server is very high, processes that are causing it are nslcd or since I changed to it sssd and the smbd processes themselves.This is the root of the problem: [2014/09/24 16:15:04.433393,? 2, pid=2495, effective(547, 500), real(547, 0)] ../source3/smbd/smb2_server.c:1784(smbd_smb2_request_v +erify_creditcharge)? CreditCharge too low, given 1, needed 2 Can you log a bug with the samba bugzilla and also upload a wireshark trace of these packets ? We'll need that to investigate & fix. Thanks ! Jeremy.