4

On a Solaris 11.1 install, I see stalls when receiving a zfs incremental stream. The streams are originating from a Solaris 11.0 install, are created using zfs send -i and piped through mbuffer. At some point in time, I can see the write performance stall occasionally (virtually no read or write activity on the destination disks, mpstat reporting utilization on the same or different cores summing up to slightly above 100% for "system", with 0 other load):

root@receiver:~# mpstat 5
[...]
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    0   0    0   363  103  213    0    9    4    0    14    0   6   0  94
   1    0   0    0   113    3  149    0   11    6    0    16    0  12   0  88
   2    1   0    2    40    4   36    0    9    5    0     3    0   1   0  99
   3    0   0    0    82   59   18    0    2    3    0     3    0  93   0   7
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    3   0    0   362  104  207    0    9    6    0    12    0  14   0  86
   1    0   0    0    90    4  109    0   10    7    0     3    0  17   0  83
   2    0   0    0    48    2   40    0    9    3    0     5    0  10   0  90
   3    0   0    0   100   54   44    0    7    3    0     4    0  69   0  31
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    0   0    0   332  103   35    0    6    3    0     0    0  45   0  55
   1    0   0    0    27    3   22    0    3    1    0     0    0  45   0  55
   2    0   0    0   142    3  172    0    9    6    0     4    0  18   0  82
   3    0   0    0   181   56  178    0   10    6    0     8    0   1   0  99
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    0   0    0   327  103   54    0    5    2    0     2    0  49   0  51
   1    0   0    0    46    3   52    0    9    3    0     0    0  28   0  72
   2    0   0    0   156    2  175    0    9    5    0     4    0  25   0  75
   3    0   0    0   153   62  132    1    8    6    0     5    0   3   0  97
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    0   0    1   380  103  164    0   11    9    0     7    0   5   0  95
   1    0   0    0   144    3  165    0   11    9    0     6    0  25   0  75
   2    0   0    0    39    1   36    0    6    4    0     2    0  66   0  34
   3    0   0    0   125   77   55    0   10    6    0     1    0  14   0  86
 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
   0    0   0    0   372  107  178    0    9    9    0    19    0   3   0  97
   1    0   0    0   145    3  193    0    9   10    0     8    0   8   0  92
   2    0   0    0    24    2   26    0    9    3    0     0    0   2   0  98
   3    0   0    0    94   86    3    0    0    5    0     0    0 100   0   0

After another 200-300 MBs written in bursts, the transfer nearly comes to a halt:

root@receiver:~# zpool iostat tank 5
               capacity     operations    bandwidth
pool        alloc   free   read  write   read  write
----------  -----  -----  -----  -----  -----  -----
tank        1.85T  2.01T    511    831  7.76M  4.60M
tank        1.85T  2.01T      0     26      0  65.4K
tank        1.85T  2.01T      3     25  13.2K  62.4K
tank        1.85T  2.01T      4     34  5.00K  76.2K
tank        1.85T  2.01T      3     32  3.10K  87.0K
tank        1.85T  2.01T      0     25  1.20K  59.0K
tank        1.85T  2.01T      6     58  4.30K   339K
tank        1.85T  2.01T      1     28  3.70K  63.1K
tank        1.85T  2.01T     19     30  36.9K  83.2K

And the mbuffers at the receiving and the sending ends are at 100% utilization.

This only seems to happen with larger (> 5G) snapshots, I do see the stalls towards the end of the stream, after the first GBs have been successfully transferred in a reasonable time. The stream reception is still working, just very slowly - the data rate is below 100 KB/s (from the receiving side mbuffer's memory to the idle disks).

I also have tried taking mbuffer out of the equation and pipe the zfs send stream through SSH directly into the zfs receive, but it seems to make no significant difference. The snapshot eventually gets transferred, but the last 1-2 gigs would take hours.

The receiving host is otherwise completely idle, no messages are printed to the console, the kernel message log or /var/log/syslog at that time. The destination zpool remains usable - I still can access other filesystems located in the same zpool at all times. Also, receiving complete, non-incremental / non-recursive zfs streams of hundreds of GB in size works without any preceptable issues at wire speed.

Is there a known problem with 11.1 regarding this issue? How could I further diagnose what the receiver is waiting for when it should write the stream?

2
  • Probably a bug. Can you show your command string?
    – ewwhite
    May 16, 2013 at 9:48
  • @ewwhite Nothing fancy: ssh ${REMOTE} "/opt/csw/bin/mbuffer -q -m 100M -I 9090 | /usr/sbin/zfs receive -F ${V}" & sleep 2 && zfs send -i $OLDSNAP $NEWSNAP | /opt/csw/bin/mbuffer -m 100M -O ${REMOTE}:9090. Without mbuffer it is even more simplistic: zfs send -i $OLDSNAP $NEWSNAP | ssh -c arcfour ${REMOTE} "/usr/sbin/zfs receive -F ${V}"
    – the-wabbit
    May 16, 2013 at 10:14

1 Answer 1

5

Both the zfs send and the zfs receive are tied to each other when you pipe them together like this. The source system has to crawl the zfs metadata looking for blocks that were written within the incremental interval you are sending. You're then piping that to mbuffer, so that the stream across the ssh session can be somewhat optimized by presenting a bucket on each end that can mitigate stalling and overruns. Then the pipe from mbuffer feeds data into a zfs receive which has to process the incoming data exactly as if it were being written. So, X number of transactions per transaction group, flush to disk, calculate the metadata, and write it all out, all the way up to the uberblock. This can look very much like stalls in the stream, and can generally last from 5 to 30 seconds. If these drops in throughput are lasting longer than 30 seconds, you're probably resource bound somewhere.

Depending on how your system is tuned, for example, do you have a fast ZIL SLOG? Or do you have a very large number of spindles behind your zpool to optimize on logbias=throughput? Depending on the answers to questions like that, you'll be able to determine if you are resource bound somewhere or not.

Your CPUS don't look too badly beat up. I see servers on a daily basis with ZPOOLs sized at 250+TB that have mpstat intr column counts up over 20,000. More cpus always improves mpstat numbers.

I would look at some of the dtrace scripts like zilstat, arcstat, and iopattern among others (check the DtraceToolkit) to see what the system is doing during your pauses.

7
  • Excellent!! Good explanation.
    – ewwhite
    May 17, 2013 at 20:47
  • Tim, thank you for your hints. My stalls indeed are significantly longer than 30 seconds - at the end of the transfer, they might take hours (this seems to somewhat depend on the total size of the snapshot transferred). zilstat is mostly showing all-zeroes, with infrequent negligible activity (3-5 ops, after that silence again). Arcstat has been somewhat broken in S11, but from what I see, the disks have a low read rate (somewhere in the low-hundreds per second and a miss percentage of 20-40).
    – the-wabbit
    May 19, 2013 at 10:30
  • It appears that zfs receive is single-threaded and the process is indeed resource-bound by the slowish single-thread performance of the CPU (it is a repurposed lab system with AMD Opteron 2212 CPUs). I am still unclear however about why this is so. I could not find people reporting about similar problems and I have not seen this before with older Solaris versions (nor with Nexenta).
    – the-wabbit
    May 19, 2013 at 10:33
  • @syneticon-dj how big are the snapshots you're replicating? On a system where we're moving up to 1TB/day it's not uncommon to see 4-5 hours spent in zfs send, and another 5-6 hours in zfs recv, not including transport time across the network. Much of that time it doesn't look like anything is happening. If the recv has finished with the data available to it, it may be waiting on the send to provide more data. Have you checked that both the send and receive are stalled during one of your low I/O periods? May 19, 2013 at 15:19
  • Tim, the snapshots are not nearly as large (5-30 GB). As both ends are connected through mbuffer, I would be able to identify the sending side as the bottleneck, if this were the case - it is not, the receiver is stalling - and after the buffers are filled, the sender obviously has virtually nothing to do. The stalls always happen towards the end of the transfer, no matter the size. Do you know of any way to see where the zfs receive is spending its CPU time? I tried lockstat without any enlightning results, but I simply might have got the wrong option set for that.
    – the-wabbit
    May 19, 2013 at 16:11

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .