SOLVED Sudden Terrible SMB performance

Constantin

Vampire Pig
Joined
May 19, 2017
Messages
1,828
Good evening,

I recently switched to TrueNAS 12 and am running TrueNAS-12.0-U2.1. As I mentioned before, I have tried to take advantage of special vdevs (via 3 mirrored S3610 SSDs), etc. by nuking the pool and rebuilding it from the ground up, then restoring from backup. Along the way, I learned a thing or two about ACLs because the new pool only uses SMB instead of AFP. I have been slowly inching my way towards getting the pool fully set up when I ran into serious performance issues starting yesterday.

I started seeing the telltale signs of a bad SMB process while trying to delete empty files. File renames and deletes would take very long time instead of being instantaneous as I had gotten used to with the new SSD metadata.
Screen Shot 2021-04-07 at 2.13.32 PM.png

Screen Shot 2021-04-07 at 1.53.46 PM.png


SMBD is taking up all the thread capacity. Gstat shows no activity to speak of, ditto our network interface.
Screen Shot 2021-04-07 at 2.09.38 PM.png


Cat the SMB Error logs though and there is a torrent of error messages. Here is a selection of messages but each message literally has lots of instances each.

Code:
[2021/04/07 00:17:24.532299,  1] ../../source3/rpc_server/srv_pipe_hnd.c:103(np_open)
  np_open: 'mdssvc' is not a registered pipe!
 
 ....
 
[2021/04/07 00:39:42.350377,  1] ../../source3/smbd/scavenger.c:486(scavenger_timer)
  scavenger_timer: Failed to cleanup share modes and byte range locks for file 4758002284915082683:390:0 open 1183922632
 
  ...
 
  [2021/04/07 07:58:41.358773,  0] ../../source3/modules/vfs_ixnas.c:2300(ixnas_ntimes)
  ixnas_ntimes: utimensat failed: No such file or directory
 
  ...
 
  [2021/04/07 09:10:39.011705,  1] ../../source3/smbd/scavenger.c:486(scavenger_timer)
  scavenger_timer: Failed to cleanup share modes and byte range locks for file 4758002284915082683:2924:0 open 3686271052
 
  ...
 
 
  [2021/04/07 09:10:39.022767, 1] ../../source3/smbd/scavenger.c:486(scavenger_timer)
scavenger_timer: Failed to cleanup share modes and byte range locks for file 4758002284915082683:25467:0 open 3332239265

...

[2021/04/07 10:13:39.191945, 0] ../../source3/modules/vfs_ixnas.c:2300(ixnas_ntimes)
ixnas_ntimes: utimensat failed: No such file or directory
[2021/04/07 10:13:49.773403, 0] ../../source3/smbd/server.c:1782(main)
smbd version 4.12.9 started.
Copyright Andrew Tridgell and the Samba Team 1992-2020
[2021/04/07 10:13:49.780627, 1] ../../source3/profile/profile.c:55(set_profile_level)
INFO: Profiling turned OFF from pid 59797
[2021/04/07 10:13:50.046111, 1] ../../source3/smbd/files.c:223(file_init_global)
file_init_global: Information only: requested 3770496 open files, 59392 are available.
[2021/04/07 10:13:50.050138, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
[2021/04/07 10:14:29.344871, 0] ../../source3/smbd/server.c:1782(main)
smbd version 4.12.9 started.
Copyright Andrew Tridgell and the Samba Team 1992-2020
[2021/04/07 10:14:29.351094, 1] ../../source3/profile/profile.c:55(set_profile_level)
INFO: Profiling turned OFF from pid 59989
[2021/04/07 10:14:29.599776, 1] ../../source3/smbd/files.c:223(file_init_global)
file_init_global: Information only: requested 3770496 open files, 59392 are available.
[2021/04/07 10:14:29.603268, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
[2021/04/07 10:45:25.500328, 1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
Failed to fetch record!
[2021/04/07 10:45:25.500385, 1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
pcap cache not loaded
[2021/04/07 10:45:26.992197, 1] ../../source3/rpc_server/srv_pipe_hnd.c:103(np_open)
np_open: 'mdssvc' is not a registered pipe!

...

[2021/04/07 11:13:40.775732, 1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
Failed to fetch record!
[2021/04/07 11:13:40.775880, 1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
pcap cache not loaded
[2021/04/07 11:14:00.140837, 1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
Failed to fetch record!
[2021/04/07 11:14:00.140880, 1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
pcap cache not loaded

...


2021/04/07 13:18:42.632283, 0] ../../source3/smbd/server.c:1782(main)
smbd version 4.12.9 started.
Copyright Andrew Tridgell and the Samba Team 1992-2020
[2021/04/07 13:18:42.647292, 1] ../../source3/profile/profile.c:55(set_profile_level)
INFO: Profiling turned OFF from pid 3606
[2021/04/07 13:18:42.930005, 0] ../../source3/smbd/server.c:1782(main)
smbd version 4.12.9 started.
Copyright Andrew Tridgell and the Samba Team 1992-2020
[2021/04/07 13:18:42.935044, 1] ../../source3/profile/profile.c:55(set_profile_level)
INFO: Profiling turned OFF from pid 3626
[2021/04/07 13:18:42.935860, 0] ../../lib/util/pidfile.c:197(pidfile_create)
ERROR: smbd is already running. File /var/run/samba4/smbd.pid exists and process id 3608 is running.
[2021/04/07 13:18:42.996190, 1] ../../source3/smbd/files.c:223(file_init_global)
file_init_global: Information only: requested 3770496 open files, 59392 are available.
[2021/04/07 13:18:43.004326, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
[2021/04/07 13:20:11.004756, 1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
Failed to fetch record!
[2021/04/07 13:20:11.004801, 1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
pcap cache not loaded

..

[2021/04/07 13:40:41.424242, 1] ../../source3/smbd/files.c:223(file_init_global)
file_init_global: Information only: requested 3770496 open files, 59392 are available.
[2021/04/07 13:40:41.427876, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
[2021/04/07 13:51:22.605615, 1] ../../source3/rpc_server/srv_pipe_hnd.c:103(np_open)
np_open: 'mdssvc' is not a registered pipe!
[2021/04/07 14:21:44.276087, 0] ../../source3/smbd/server.c:1782(main)
smbd version 4.12.9 started.
Copyright Andrew Tridgell and the Samba Team 1992-2020
[2021/04/07 14:21:44.282156, 1] ../../source3/profile/profile.c:55(set_profile_level)
INFO: Profiling turned OFF from pid 6436
[2021/04/07 14:21:44.524169, 1] ../../source3/smbd/files.c:223(file_init_global)
file_init_global: Information only: requested 3770496 open files, 59392 are available.
[2021/04/07 14:21:44.527982, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
[2021/04/07 14:22:12.740894, 1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
Failed to fetch record!
[2021/04/07 14:22:12.740995, 1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
pcap cache not loaded
[2021/04/07 14:22:13.959709, 1] ../../source3/rpc_server/srv_pipe_hnd.c:103(np_open)
np_open: 'mdssvc' is not a registered pipe!


Does anyone know what might be going on?
 

Constantin

Vampire Pig
Joined
May 19, 2017
Messages
1,828
Kids, don't be stupid like Constantin and add a NTP server without knowing that it agrees with all the other NTP servers in the pool. For example, do not add a local gateway as a NTP server in addition to the pools that are in there by default. Bad things will happen.
 

rogerh

Guru
Joined
Apr 18, 2014
Messages
1,111
Kids, don't be stupid like Constantin and add a NTP server without knowing that it agrees with all the other NTP servers in the pool. For example, do not add a local gateway as a NTP server in addition to the pools that are in there by default. Bad things will happen.
If your local gateway ntp server is properly synced with a pool of remote ntp servers, wouldn't it make sense to use it as the only ntp server for other machines on the local network?
 

Constantin

Vampire Pig
Joined
May 19, 2017
Messages
1,828

Andreaux

Dabbler
Joined
Nov 17, 2019
Messages
20
Hello folks,
I just ran into a similar looking issue, in a sense that I have the same flood of errors in log.smbd.
However, out of the replies above, I can't make out what the solution is/was.
Can anyone explain? I don't have any custom NTP servers set, my box is vanilla in this regard.
 

Constantin

Vampire Pig
Joined
May 19, 2017
Messages
1,828
I’d look into whether your box can reach the pool of ntp servers it is supposed to use or not. Some users here reported issues with getting blocked by their ISP, etc. So I’d try a manual refresh from the shell first and let us know how it worked out.
 
Top