Bad performance with replication

vjk · May 26, 2016, 2:02am

We are considering Aerospike as an alternative to Cassandra.

So, we tested one node write performance using performance tweaks as recommended by Aerospike. With one node cluster and two node clients we can see 610K tps with the benchmark tool. With one client we are seeing 310K tps.

However, when we try the same benchmark on a two node cluster with the replication level == 2, performance drops 4 times from 310K tps to only 75K tps. Is it “normal” ?

The ns configuration:

namespace test {
    replication-factor 2
    memory-size 10G 
    default-ttl 1h # 30 days, use 0 to never expire/evict.

    storage-engine memory
}

The command:

aerospike-client-c/benchmarks/target/benchmarks -h xx.xx.xx.xx -w RU,0 -z 300 -L 4,1

Thanks.

kporter · May 27, 2016, 12:25am

Just to be sure, it drops from 310K to 75K tps as seen by the client or server?

vjk · May 27, 2016, 1:13am

By both. Each node 's tps drops to about 40K tps.

When I run one client - one node cluster, “sar -n DEV 1” shows roughly the number of packets/sec on eth0 to be roughly the same as the number of tps, i.e. 320K/sec. Then, when I run the same client against two nodes with rep level == 2, the number of tps falls to 75K, and the number of packets on eth0 is about 180K/sec. So, there appears to be plenty of room for the server to run: cpu usage is about 2-3%, irq% is about 0.6%:

Tasks: 247 total,   1 running, 246 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.2%us,  0.2%sy,  0.0%ni, 98.8%id,  0.0%wa,  0.0%hi,  0.6%si,  0.2%st
Mem:  251902544k total,   937992k used, 250964552k free,    59236k buffers
Swap:        0k total,        0k used,        0k free,   139780k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                 
 12547 root      20   0 6876m 136m 4252 S 953.8  0.1   7:11.68 asd                                                                     
     3 root      20   0     0    0    0 S 23.7  0.0   9:19.44 ksoftirqd/0                                                              
    12 root      20   0     0    0    0 S 19.7  0.0   6:47.23 ksoftirqd/1                                                              
  3625 root      20   0  4380   84    0 S  7.9  0.0   7:17.03 rngd                                                                     
    16 root      20   0     0    0    0 S  2.0  0.0   0:03.27 ksoftirqd/2

It looks as if the server is intentionally sleeping. As I mentioned before, with two clients and one node, I could generate 620K tps (with about the same packets/sec rate ) on the server side. I did not try more clients because I wanted to sort out the replication performance drop first.

kporter · June 1, 2016, 11:57pm

Going from 1 to 2 nodes with replication factor 2 we typically observer ~50% peak TPS reduction which is expected since each write is amplified a factor of 2.

So a 4X reduction isn’t expected. As for the number of packets, there is not a 1 to 1 relation to the number of writes to the number of packets generated by replica writes. The intra-cluster fabric layer opportunistically coalesces messages to a given node so it is possible multiple replica writes are sent in a single packet. How do the number of bytes compare in sar?

Also with your top output, could you open top and press “1” so we can see how the load is being distributed across the node’s cores.

vjk · June 2, 2016, 1:47am

Hi,

The command: aerospike-client-c/benchmarks/target/benchmarks -h 10.55.2.166 -o B:100 -w RU,0 -z 300 -L 4,1

Here’s the distribution for one client/one node cluster (310K tps):

top - 01:32:45 up 7 days, 44 min,  1 user,  load average: 1.97, 0.83, 0.35
Tasks: 266 total,   2 running, 264 sleeping,   0 stopped,   0 zombie
Cpu0  :  9.1%us,  8.7%sy,  0.0%ni,  3.8%id,  0.0%wa,  0.0%hi, 78.3%si,  0.0%st
Cpu1  :  7.2%us,  8.6%sy,  0.0%ni,  3.1%id,  0.0%wa,  0.0%hi, 81.0%si,  0.0%st
Cpu2  : 20.2%us, 19.1%sy,  0.0%ni, 27.0%id,  0.0%wa,  0.0%hi, 33.1%si,  0.6%st
Cpu3  : 18.8%us, 18.8%sy,  0.0%ni, 23.6%id,  0.0%wa,  0.0%hi, 37.7%si,  1.0%st
Cpu4  :  3.6%us,  5.3%sy,  0.0%ni, 89.9%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu5  :  6.4%us,  2.3%sy,  0.0%ni, 89.5%id,  0.0%wa,  0.0%hi,  0.0%si,  1.8%st
Cpu6  :  4.1%us,  5.2%sy,  0.0%ni, 89.5%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu7  :  5.1%us,  4.0%sy,  0.0%ni, 89.1%id,  0.0%wa,  0.0%hi,  0.0%si,  1.7%st
Cpu8  :  0.0%us,  0.4%sy,  0.0%ni, 98.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu9  :  0.4%us,  0.4%sy,  0.0%ni, 98.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu10 :  0.0%us,  0.4%sy,  0.0%ni, 98.2%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu11 :  0.4%us,  0.9%sy,  0.0%ni, 97.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu12 :  0.0%us,  0.0%sy,  0.0%ni, 99.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu13 :  0.4%us,  0.4%sy,  0.0%ni, 97.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu14 :  0.4%us,  1.3%sy,  0.0%ni, 97.0%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu15 :  0.9%us,  0.4%sy,  0.0%ni, 97.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu16 :  1.6%us,  2.6%sy,  0.0%ni, 94.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu17 :  2.1%us,  0.5%sy,  0.0%ni, 96.4%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu18 :  5.0%us,  4.5%sy,  0.0%ni, 88.9%id,  0.0%wa,  0.0%hi,  0.0%si,  1.5%st
Cpu19 :  4.6%us,  4.6%sy,  0.0%ni, 89.3%id,  0.0%wa,  0.0%hi,  0.0%si,  1.5%st
Cpu20 :  4.1%us,  2.1%sy,  0.0%ni, 92.2%id,  0.0%wa,  0.0%hi,  0.0%si,  1.6%st
Cpu21 :  2.1%us,  3.2%sy,  0.0%ni, 93.7%id,  0.0%wa,  0.0%hi,  0.0%si,  1.1%st
Cpu22 :  2.6%us,  3.1%sy,  0.0%ni, 92.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.5%st
Cpu23 :  1.6%us,  3.2%sy,  0.0%ni, 94.1%id,  0.0%wa,  0.0%hi,  0.0%si,  1.1%st
Cpu24 :  0.4%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu25 :  0.0%us,  0.4%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu26 :  0.0%us,  0.4%sy,  0.0%ni, 99.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu27 :  0.4%us,  0.0%sy,  0.0%ni, 99.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu28 :  0.4%us,  0.4%sy,  0.0%ni, 98.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu29 :  0.4%us,  0.4%sy,  0.0%ni, 98.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu30 :  0.0%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu31 :  0.0%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Mem:  251902544k total,  1624312k used, 250278232k free,   141408k buffers

And here’s the distribution for one client/two-node cluster(82K tps):

top - 01:38:16 up 7 days, 50 min,  1 user,  load average: 3.04, 2.30, 1.19
Tasks: 266 total,   1 running, 265 sleeping,   0 stopped,   0 zombie
Cpu0  :  8.8%us, 10.2%sy,  0.0%ni, 12.1%id,  0.0%wa,  0.0%hi, 68.4%si,  0.5%st
Cpu1  : 12.4%us, 13.4%sy,  0.0%ni, 15.3%id,  0.0%wa,  0.0%hi, 58.4%si,  0.5%st
Cpu2  :  6.9%us,  9.0%sy,  0.0%ni, 74.5%id,  0.0%wa,  0.0%hi,  6.9%si,  2.8%st
Cpu3  :  8.7%us, 12.8%sy,  0.0%ni, 62.4%id,  0.0%wa,  0.0%hi, 14.1%si,  2.0%st
Cpu4  :  5.0%us,  3.0%sy,  0.0%ni, 91.1%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu5  :  3.5%us,  4.5%sy,  0.0%ni, 91.0%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu6  :  2.5%us,  3.0%sy,  0.0%ni, 93.5%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu7  :  2.5%us,  3.0%sy,  0.0%ni, 93.5%id,  0.0%wa,  0.0%hi,  0.0%si,  1.0%st
Cpu8  :  7.7%us,  1.8%sy,  0.0%ni, 86.9%id,  2.3%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu9  :  5.9%us,  2.3%sy,  0.0%ni, 87.8%id,  2.7%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu10 :  7.7%us,  2.3%sy,  0.0%ni, 86.5%id,  2.3%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu11 :  5.0%us,  1.8%sy,  0.0%ni, 89.0%id,  2.7%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu12 :  6.3%us,  3.2%sy,  0.0%ni, 87.3%id,  2.3%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu13 :  6.4%us,  2.3%sy,  0.0%ni, 88.6%id,  1.8%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu14 :  4.6%us,  1.4%sy,  0.0%ni, 91.3%id,  1.4%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu15 :  7.1%us,  2.7%sy,  0.0%ni, 86.6%id,  2.2%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu16 :  3.6%us,  3.6%sy,  0.0%ni, 92.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu17 :  3.2%us,  4.1%sy,  0.0%ni, 91.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu18 :  2.7%us,  1.8%sy,  0.0%ni, 94.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu19 :  2.3%us,  3.6%sy,  0.0%ni, 93.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu20 :  1.4%us,  1.4%sy,  0.0%ni, 96.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu21 :  0.9%us,  1.4%sy,  0.0%ni, 96.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu22 :  1.8%us,  3.2%sy,  0.0%ni, 94.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.9%st
Cpu23 :  0.9%us,  3.6%sy,  0.0%ni, 94.2%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu24 :  2.6%us,  0.9%sy,  0.0%ni, 94.4%id,  0.9%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu25 :  1.7%us,  0.4%sy,  0.0%ni, 95.7%id,  0.9%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu26 :  1.3%us,  0.4%sy,  0.0%ni, 95.2%id,  1.3%wa,  0.0%hi,  0.0%si,  1.7%st
Cpu27 :  2.1%us,  0.0%sy,  0.0%ni, 95.7%id,  0.9%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu28 :  1.3%us,  1.3%sy,  0.0%ni, 95.7%id,  0.4%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu29 :  3.4%us,  1.3%sy,  0.0%ni, 93.2%id,  0.9%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu30 :  1.7%us,  1.3%sy,  0.0%ni, 95.2%id,  0.4%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu31 :  1.3%us,  0.9%sy,  0.0%ni, 95.7%id,  0.9%wa,  0.0%hi,  0.0%si,  1.3%st

As you can see, the load (mainly irq cpu) is lower with two nodes, but throughput is also lower.

One node dstat:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0  99   0   0   0| 322k   24k|   0     0 |   0     0 |  19k   14k
  3   3  86   0   0   8|   0     0 |  73M   27M|   0     0 | 336k  315k
  3   3  86   0   0   8|   0     0 |  72M   27M|   0     0 | 337k  314k
  3   3  86   0   0   8|   0     0 |  73M   27M|   0     0 | 338k  317k
  3   3  87   0   0   7|   0     0 |  71M   26M|   0     0 | 339k  314k
  2   3  87   0   0   8|   0     0 |  73M   27M|   0     0 | 335k  316k
  3   3  86   0   0   8|   0     0 |  73M   27M|   0     0 | 337k  316k
  3   3  85   0   0   8|   0     0 |  75M   28M|   0     0 | 333k  313k
  3   3  86   0   0   8|   0     0 |  74M   28M|   0     0 | 340k  318k
  3   3  86   0   0   8|   0     0 |  75M   28M|   0     0 | 347k  325k

One node sar:

sar -n DEV 1
Linux 4.4.8-20.46.amzn1.x86_64 (ip-10-55-2-166)     06/02/2016     _x86_64_    (32 CPU)

01:43:30 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:43:31 AM      eth0 322360.22 322343.01  80904.10  30219.70      0.00      0.00      0.00
01:43:31 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

01:43:31 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:43:32 AM      eth0 341315.91 341250.00  85642.98  31992.44      0.00      0.00      0.00
01:43:32 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

01:43:32 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:43:33 AM      eth0 341445.45 341497.73  85694.22  32015.78      0.00      0.00      0.00
01:43:33 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

Two nodes dstat:

dstat
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0  99   0   0   0| 322k   24k|   0     0 |   0     0 |  19k   13k
  4   3  89   1   0   4| 897k    0 |  30M   28M|   0     0 | 425k  392k
  4   3  89   0   0   4| 149k    0 |  31M   28M|   0     0 | 413k  389k
  4   3  90   0   0   4|   0    32k|  31M   28M|   0     0 | 416k  391k
  4   3  90   0   0   4|   0     0 |  30M   28M|   0     0 | 408k  382k
  3   3  90   0   0   4|   0     0 |  30M   28M|   0     0 | 419k  384k
  4   3  90   0   0   3|   0     0 |  31M   28M|   0     0 | 418k  388k
  4   3  90   0   0   4|   0     0 |  30M   27M|   0     0 | 412k  380k
  3   3  90   0   0   4|   0     0 |  30M   27M|   0     0 | 420k  383k
  4   3  89   1   0   4| 632k   10M|  31M   28M|   0     0 | 414k  386k
  4   3  88   1   0   4| 895k   16M|  31M   28M|   0     0 | 409k  387k
  4   3  89   1   0   4| 904k   16M|  30M   28M|   0     0 | 417k  392k
  3   3  89   1   0   4| 902k   16M|  30M   28M|   0     0 | 413k  387k

Two node cluster sar:

01:46:48 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:46:49 AM      eth0 197400.00 191634.92  45825.60  36401.26      0.00      0.00      0.00
01:46:49 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

01:46:49 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:46:50 AM      eth0 212863.79 211029.31  49966.82  39905.64      0.00      0.00      0.00
01:46:50 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

01:46:50 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:46:51 AM      eth0 188024.62 190293.85  44468.70  35797.17      0.00      0.00      0.00
01:46:51 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

01:46:51 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s
01:46:52 AM      eth0 207218.03 192340.98  47433.24  37260.85      0.00      0.00      0.00
01:46:52 AM        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.00

kporter · June 2, 2016, 11:08pm

Looks as if cores 0 and 1 may be servicing all network requests. If you have a quality NIC it will have multiple TX/RX queues each serviced through interrupts. We have observed that around Linux kernel version 3.10 these interrupts began to be distributed across the cores better. Prior to that Aerospike has shipped with an afterburner utility where one of its functions is to distribute these interrupts.

Could we take a look at /proc/interrupts

vjk · June 3, 2016, 1:10am

The 244/245 eth0 interrupts were assigned to cpu0/1 by running the after-burn script. Here’s /proc/interrupts (Part 1):

            CPU0       CPU1       CPU2       CPU3       CPU4       CPU5       CPU6       CPU7       CPU8       CPU9       CPU10      CPU11      CPU12      CPU13      CPU14      CPU15      CPU16      CPU17      CPU18      CPU19      CPU20      CPU21      CPU22      CPU23      CPU24      CPU25      CPU26      CPU27      CPU28      CPU29      CPU30      CPU31      
   0:         62          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC    2-edge      timer
   1:          9          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-pirq    1-ioapic-edge  i8042
   4:        485          0          0          0          0          0          0          0          0          0        136          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-pirq    4-ioapic-edge  serial
   9:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-pirq    9-ioapic-level  acpi
  12:         86          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-pirq   12-ioapic-edge  i8042
  14:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC   14-edge      ata_piix
  15:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC   15-edge      ata_piix
  48:    1353368          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer0
  49:  600692644          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched0
  50:        239          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc0
  51:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug0
  52:  410535273          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle0
  53:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock0
  54:          0    1119892          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer1
  55:          0  431587612          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched1
  56:          0        280          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc1
  57:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug1
  58:          0  402286956          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle1
  59:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock1
  60:          0          0     726759          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer2
  61:          0          0  460647690          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched2
  62:          0          0        255          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc2
  63:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug2
  64:          0          0  786450919          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle2
  65:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock2
  66:          0          0          0    1294863          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer3
  67:          0          0          0  427920526          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched3
  68:          0          0          0        262          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc3
  69:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug3
  70:          0          0          0  861647307          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle3
  71:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock3
  72:          0          0          0          0     607445          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer4
  73:          0          0          0          0  606662195          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched4
  74:          0          0          0          0        236          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc4
  75:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug4

vjk · June 3, 2016, 1:10am

Part 2:

  76:          0          0          0          0        950          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle4
  77:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock4
  78:          0          0          0          0          0     609494          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer5
  79:          0          0          0          0          0  580719105          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched5
  80:          0          0          0          0          0        252          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc5
  81:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug5
  82:          0          0          0          0          0        856          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle5
  83:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock5
  84:          0          0          0          0          0          0     604825          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer6
  85:          0          0          0          0          0          0  558440190          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched6
  86:          0          0          0          0          0          0        287          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc6
  87:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug6
  88:          0          0          0          0          0          0        812          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle6
  89:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock6
  90:          0          0          0          0          0          0          0     598590          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer7
  91:          0          0          0          0          0          0          0  541533382          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched7
  92:          0          0          0          0          0          0          0        435          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc7
  93:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug7
  94:          0          0          0          0          0          0          0        856          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle7
  95:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock7
  96:          0          0          0          0          0          0          0          0     524326          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer8
  97:          0          0          0          0          0          0          0          0   31926073          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched8
  98:          0          0          0          0          0          0          0          0        244          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc8
  99:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug8
 100:          0          0          0          0          0          0          0          0       1172          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle8
 101:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock8
 102:          0          0          0          0          0          0          0          0          0     467579          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer9
 103:          0          0          0          0          0          0          0          0          0   32562068          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched9
 104:          0          0          0          0          0          0          0          0          0        226          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc9
 105:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug9
 106:          0          0          0          0          0          0          0          0          0       1176          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle9
 107:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock9
 108:          0          0          0          0          0          0          0          0          0          0     463387          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer10
 109:          0          0          0          0          0          0          0          0          0          0   30568679          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched10
 110:          0          0          0          0          0          0          0          0          0          0        265          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc10
 111:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug10
 112:          0          0          0          0          0          0          0          0          0          0       1259          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle10
 113:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock10
 114:          0          0          0          0          0          0          0          0          0          0          0     459469          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer11
 115:          0          0          0          0          0          0          0          0          0          0          0   31016208          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched11
 116:          0          0          0          0          0          0          0          0          0          0          0        234          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc11
 117:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug11
 118:          0          0          0          0          0          0          0          0          0          0          0       1190          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle11
 119:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock11
 120:          0          0          0          0          0          0          0          0          0          0          0          0     615359          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer12
 121:          0          0          0          0          0          0          0          0          0          0          0          0   30825022          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched12
 122:          0          0          0          0          0          0          0          0          0          0          0          0        257          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc12
 123:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug12
 124:          0          0          0          0          0          0          0          0          0          0          0          0       1122          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle12
 125:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock12
 126:          0          0          0          0          0          0          0          0          0          0          0          0          0     458520          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer13
 127:          0          0          0          0          0          0          0          0          0          0          0          0          0   31135290          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched13
 128:          0          0          0          0          0          0          0          0          0          0          0          0          0        254          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc13
 129:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug13
 130:          0          0          0          0          0          0          0          0          0          0          0          0          0       1153          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle13
 131:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock13
 132:          0          0          0          0          0          0          0          0          0          0          0          0          0          0     679381          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer14
 133:          0          0          0          0          0          0          0          0          0          0          0          0          0          0   32172714          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched14
 134:          0          0          0          0          0          0          0          0          0          0          0          0          0          0        272          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc14
 135:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug14
 136:          0          0          0          0          0          0          0          0          0          0          0          0          0          0       1156          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle14
 137:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock14
 138:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0    1028752          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer15
 139:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   32834137          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched15
 140:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        265          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc15
 141:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug15
 142:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0       1161          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle15
 143:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock15
 144:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     447096          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer16
 145:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  158207534          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched16
 146:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        189          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc16
 147:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug16
 148:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        526          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle16
 149:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock16
 150:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     451937          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      timer17
 151:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  163500085          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       resched17

vjk · June 3, 2016, 1:12am

 189:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug23
 190:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        616          0          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle23
 191:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock23
 192:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     418615          0          0          0          0          0          0          0  xen-percpu-virq      timer24
 193:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   12328319          0          0          0          0          0          0          0  xen-percpu-ipi       resched24
 194:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        141          0          0          0          0          0          0          0  xen-percpu-ipi       callfunc24
 195:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug24
 196:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        746          0          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle24
 197:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock24
 198:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     439269          0          0          0          0          0          0  xen-percpu-virq      timer25
 199:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   12500806          0          0          0          0          0          0  xen-percpu-ipi       resched25
 200:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        148          0          0          0          0          0          0  xen-percpu-ipi       callfunc25
 201:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug25
 202:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        768          0          0          0          0          0          0  xen-percpu-ipi       callfuncsingle25
 203:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock25
 204:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     386426          0          0          0          0          0  xen-percpu-virq      timer26
 205:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   11168876          0          0          0          0          0  xen-percpu-ipi       resched26
 206:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        147          0          0          0          0          0  xen-percpu-ipi       callfunc26
 207:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug26
 208:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        692          0          0          0          0          0  xen-percpu-ipi       callfuncsingle26
 209:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock26
 210:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     386836          0          0          0          0  xen-percpu-virq      timer27
 211:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   10828283          0          0          0          0  xen-percpu-ipi       resched27
 212:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        167          0          0          0          0  xen-percpu-ipi       callfunc27
 213:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug27
 214:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        664          0          0          0          0  xen-percpu-ipi       callfuncsingle27
 215:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock27
 216:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     389576          0          0          0  xen-percpu-virq      timer28
 217:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   12060162          0          0          0  xen-percpu-ipi       resched28
 218:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        161          0          0          0  xen-percpu-ipi       callfunc28
 219:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug28
 220:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        659          0          0          0  xen-percpu-ipi       callfuncsingle28
 221:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock28
 222:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     387022          0          0  xen-percpu-virq      timer29
 223:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   11743811          0          0  xen-percpu-ipi       resched29
 224:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        160          0          0  xen-percpu-ipi       callfunc29
 225:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug29
 226:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        708          0          0  xen-percpu-ipi       callfuncsingle29
 227:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock29
 228:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     859381          0  xen-percpu-virq      timer30
 229:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   10227019          0  xen-percpu-ipi       resched30
 230:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        141          0  xen-percpu-ipi       callfunc30
 231:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug30
 232:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        648          0  xen-percpu-ipi       callfuncsingle30
 233:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock30
 234:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0     385662  xen-percpu-virq      timer31
 235:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   11463803  xen-percpu-ipi       resched31
 236:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        159  xen-percpu-ipi       callfunc31
 237:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-virq      debug31
 238:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0        722  xen-percpu-ipi       callfuncsingle31
 239:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-percpu-ipi       spinlock31
 240:        387          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   xen-dyn-event     xenbus
 241:       4030          0          0          0          0          0          0      26832          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   xen-dyn-event     blkif
 242:        477          0          0          0          0          0          0          0        185          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   xen-dyn-event     blkif
 243:        195          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   xen-dyn-event     blkif
 244: 1884059548          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0      49854  xen-pirq-msi-x     eth0-TxRx-0
 245:        341 1882721486          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0      46436          0          0          0          0          0          0          0          0  xen-pirq-msi-x     eth0-TxRx-1
 246:         20          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0  xen-pirq-msi-x     eth0
 NMI:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Non-maskable interrupts
 LOC:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Local timer interrupts
 SPU:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Spurious interrupts
 PMI:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Performance monitoring interrupts
 IWI:         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10         10   IRQ work interrupts
 RTR:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   APIC ICR read retries
 RES:  600692644  431587612  460647690  427920526  606662195  580719105  558440190  541533382   31926089   32562068   30568679   31016208   30825022   31135290   32172726   32834149  158207534  163500085  207802761  213101366  155472261  154168173  154182720  154168357   12328319   12500806   11168876   10828283   12060162   11743811   10227019   11463803   Rescheduling interrupts
 CAL:  410533493  402286016  786450045  861646459         70         74         71         67         61         72         70         69         72         72         72         68         68         70         70         69         68         72         70         68         72         69         69         70         68         70         69         70   Function call interrupts
 TLB:       2019       1220       1130       1111       1116       1034       1028       1224       1355       1330       1454       1355       1307       1335       1356       1358        647        744        824        812        787        820        713        722        815        847        770        761        752        798        720        811   TLB shootdowns
 TRM:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Thermal event interrupts
 THR:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Threshold APIC interrupts
 DFR:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Deferred Error APIC interrupts
 MCE:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Machine check exceptions
 MCP:       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104       2104   Machine check polls
 HYP: 2510452110 2393041765 1210418606 1251131994  605323040  579992947  558171068  541660189   32345533   32926100   30934520   31374438   31339649   31491253   32751508   33762286  158311388  163613793  207784613  213050803  155859829  154568679  154587047  154612293   12685045   12878041   11497452   11156828   12386784   12068352   11027471   11837180   Hypervisor callback interrupts
 ERR:          0
 MIS:          0
 PIN:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Posted-interrupt notification event
 PIW:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Posted-interrupt wakeup event

In any case, as can be seen from my previous message, the nic load (pkts/s) and respectively irq% is lower when running the benchmark against a two node cluster with replication == 2 in comparison to a single node cluster and yet throughput is 4x lower. That’s what is puzzling. I do believe I tried to distribute irq’s between all cpu’s and the throughput was worse compared to running the afterburn…

Tomorrow, hopefully, we’ll try an i2.8x cluster and see if the nic performance is better there.

kporter · June 3, 2016, 5:57pm

Just realized these dstats were taken on the client. Would like to see the dstat on the servers as well.

Also you can enable microbenchmarks on the servers. Enabling these will help pinpoint where the latency hit.

Another thing you could try in increasing the number of fabric-workers to the number of cores, these are the threads that send/receive inra-cluster traffic.

Lastly, just in case you haven’t seen the AWS tuning guide: AWS Tuning Guide.

vjk · June 3, 2016, 7:14pm

So, we tried an i2.8x today. The perf ratio of replication versus no replication remains the same: 4x performance degaradation with 2x replication.

Here’s the microbencmarks info. Looks like waits are happening in wt_master_wait_prole. Does not shed much light on where the bottleneck might be:

 asinfo -v "set-config:context=service;microbenchmarks=true"
ok

asloglatency -h wt_master_wait_prole
wt_master_wait_prole
Jun 03 2016 18:57:57
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
18:58:07    10  83.07   3.61   0.00  37802.5
18:58:17    10  82.69   3.53   0.00  37974.2
18:58:27    10  81.73   4.26   0.00  37886.5
-------------- ------ ------ ------ --------
     avg        82.50   3.80   0.00  37887.0
     max        83.07   4.26   0.00  37974.2


asloglatency -h writes_net
writes_net
Jun 03 2016 18:58:57
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
18:59:07    10   0.00   0.00   0.00  36872.3
18:59:17    10   0.00   0.00   0.00  36926.8
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00  36899.0
     max         0.00   0.00   0.00  36926.8




asloglatency -h writes_internal
writes_internal
Jun 03 2016 18:59:37
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
18:59:47    10   0.13   0.00   0.00  38008.3
18:59:57    10   0.12   0.00   0.00  37854.9
-------------- ------ ------ ------ --------
     avg         0.12   0.00   0.00  37931.0
     max         0.13   0.00   0.00  38008.3


 asloglatency -h writes_prole
writes_prole
Jun 03 2016 19:00:17
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
19:00:27    10   0.20   0.00   0.00  37192.8
19:00:37    10   0.18   0.00   0.00  37149.3
-------------- ------ ------ ------ --------
     avg         0.19   0.00   0.00  37171.0
     max         0.20   0.00   0.00  37192.8

asloglatency -h writes_q_process
writes_q_process
Jun 03 2016 19:00:47
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
19:00:57    10   0.00   0.00   0.00  37669.5
19:01:07    10   0.00   0.00   0.00  37998.1
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00  37833.0
     max         0.00   0.00   0.00  37998.1

asloglatency -h writes_resolve_wait
writes_resolve_wait
Jun 03 2016 19:01:17
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
19:01:27    10   0.00   0.00   0.00      0.0
19:01:37    10   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00      0.0
     max         0.00   0.00   0.00      0.0


 asloglatency -h writes_start
writes_start
Jun 03 2016 19:01:37
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
19:01:47    10   0.00   0.00   0.00  38031.3
19:01:57    10   0.00   0.00   0.00  38078.6
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00  38054.0
     max         0.00   0.00   0.00  38078.6

The dstat output:

Client:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  1   8  89   0   0   2|  53k   92k|   0     0 |   0     0 | 176k  158k
  0   0 100   0   0   0|   0     0 |6958k   46M|   0     0 | 288k  154k
  0   0 100   0   0   0|   0     0 |6870k   46M|   0     0 | 286k  152k
  0   0 100   0   0   0|   0     0 |6876k   46M|   0     0 | 286k  152k
  0   0 100   0   0   0|   0  8192B|6898k   46M|   0     0 | 285k  152k
  0   0 100   0   0   0|   0     0 |6916k   46M|   0     0 | 286k  153k
  0   0 100   0   0   0|   0     0 |6790k   45M|   0     0 | 283k  150k
  0   0 100   0   0   0|   0     0 |6812k   46M|   0     0 | 284k  150k
  0   0 100   0   0   0|   0   720k|6961k   47M|   0     0 | 288k  154k
  0   0 100   0   0   0|   0     0 |6867k   46M|   0     0 | 285k  152k
  0   0 100   0   0   0|   0     0 |6953k   46M|   0     0 | 287k  153k
  0   0 100   0   0   0|   0     0 |6962k   47M|   0     0 | 288k  154k
  0   0 100   0   0   0|   0     0 |6893k   46M|   0     0 | 286k  152k
  0   0 100   0   0   0|   0     0 |6929k   46M|   0     0 | 286k  153k
  0   0 100   0   0   0|   0    56k|6905k   46M|   0     0 | 285k  153k
  0   0 100   0   0   0|   0     0 |6934k   46M|   0     0 | 286k  153k
  0   0 100   0   0   0|   0     0 |6826k   46M|   0     0 | 284k  151k
  0   0 100   0   0   0|   0     0 |6860k   46M|   0     0 | 285k  151k
  0   0 100   0   0   0|   0     0 |6860k   46M|   0     0 | 287k  152k
  0   0 100   0   0   0|   0     0 |6917k   46M|   0     0 | 287k  153k
  0   0 100   0   0   0|   0     0 |6961k   47M|   0     0 | 288k  154k
  0   0 100   0   0   0|   0     0 |6876k   46M|   0     0 | 286k  152k
  0   0 100   0   0   0|   0     0 |7028k   47M|   0     0 | 289k  155k
  0   0 100   0   0   0|   0  1224k|6900k   46M|   0     0 | 286k  152k
  0   0 100   0   0   0|  16k 3880k|6792k   45M|   0     0 | 284k  150k
  0   0 100   0   0   0|   0     0 |6916k   46M|   0     0 | 287k  153k
  0   0 100   0   0   0|   0     0 |6867k   46M|   0     0 | 285k  152k
  0   0 100   0   0   0|   0     0 |6868k   46M|   0     0 | 287k  151k
  0   0 100   0   0   0|   0     0 |6915k   46M|   0     0 | 287k  153k
  0   0 100   0   0   0|   0   184k|6886k   46M|   0     0 | 285k  152k
  0   0 100   0   0   0|   0     0 |6957k   46M|   0     0 | 288k  154k

Server:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  1   1  97   0   0   2|  41k   80k|   0     0 |   0     0 | 204k  192k
  1   1  97   0   0   1|   0     0 |  55M   36M|   0     0 | 446k  399k
  1   1  97   0   0   1|   0     0 |  56M   37M|   0     0 | 442k  405k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 448k  403k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 446k  404k
  1   1  97   0   0   1|   0    32k|  55M   36M|   0     0 | 442k  402k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 445k  408k
  0   1  98   0   0   1|   0     0 |  54M   36M|   0     0 | 450k  400k
  1   1  98   0   0   1|   0     0 |  55M   36M|   0     0 | 448k  406k
  1   1  97   0   0   1|   0     0 |  56M   37M|   0     0 | 452k  411k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 454k  406k
  1   1  97   0   0   1|   0     0 |  56M   37M|   0     0 | 458k  409k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 452k  406k
  0   1  98   0   0   1|   0    56k|  56M   37M|   0     0 | 455k  413k
  1   1  98   0   0   1|   0     0 |  55M   36M|   0     0 | 445k  406k
  0   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 454k  409k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 458k  409k
  1   1  98   0   0   1|   0     0 |  54M   36M|   0     0 | 452k  402k
  1   1  97   0   0   1|   0    56k|  55M   37M|   0     0 | 462k  410k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 456k  407k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 455k  408k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 455k  407k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 454k  406k
  1   1  97   0   0   1|   0     0 |  56M   37M|   0     0 | 459k  412k
  1   1  98   0   0   1|   0     0 |  55M   37M|   0     0 | 450k  407k
  1   1  98   0   0   1|   0     0 |  54M   36M|   0     0 | 457k  401k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 461k  408k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 454k  406k
  1   1  98   0   0   1|   0    56k|  55M   37M|   0     0 | 457k  405k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 454k  404k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 457k  408k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 456k  407k
  1   1  97   0   0   1|   0     0 |  56M   37M|   0     0 | 455k  414k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 450k  405k
  1   1  97   0   0   1|   0     0 |  55M   37M|   0     0 | 450k  404k^C



Top:

Client:
top - 19:10:38 up  1:19,  2 users,  load average: 0.10, 0.10, 2.26
Tasks: 252 total,   1 running, 251 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni, 96.1%id,  0.0%wa,  0.0%hi,  0.5%si,  3.4%st
Cpu1  :  0.0%us,  0.5%sy,  0.0%ni, 96.3%id,  0.0%wa,  0.0%hi,  0.5%si,  2.7%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni, 97.6%id,  0.0%wa,  0.0%hi,  0.0%si,  2.4%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni, 97.1%id,  0.0%wa,  0.0%hi,  0.0%si,  2.9%st
Cpu4  :  0.0%us,  0.4%sy,  0.0%ni, 98.4%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu5  :  0.0%us,  0.0%sy,  0.0%ni, 98.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu6  :  0.0%us,  0.0%sy,  0.0%ni, 98.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu7  :  0.0%us,  0.0%sy,  0.0%ni, 98.4%id,  0.0%wa,  0.0%hi,  0.0%si,  1.6%st
Cpu8  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu9  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu10 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu11 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu12 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu13 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu14 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu15 :  0.0%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.3%st
Cpu16 :  0.0%us,  0.0%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.7%st
Cpu17 :  0.0%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu18 :  0.0%us,  0.0%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.7%st
Cpu19 :  0.0%us,  0.0%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.7%st
Cpu20 :  0.0%us,  0.0%sy,  0.0%ni, 98.3%id,  0.0%wa,  0.0%hi,  0.4%si,  1.3%st
Cpu21 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu22 :  0.0%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.3%st
Cpu23 :  0.0%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.4%st
Cpu24 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu25 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu26 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu27 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu28 :  0.0%us,  0.0%sy,  0.0%ni, 99.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu29 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu30 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu31 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st


Server:
top - 19:10:37 up  1:39,  1 user,  load average: 0.56, 0.71, 0.60
Tasks: 252 total,   1 running, 251 sleeping,   0 stopped,   0 zombie
Cpu0  :  5.9%us, 13.3%sy,  0.0%ni, 46.7%id,  0.0%wa,  0.0%hi, 32.6%si,  1.5%st
Cpu1  :  2.4%us,  1.8%sy,  0.0%ni, 91.7%id,  0.0%wa,  0.0%hi,  1.8%si,  2.4%st
Cpu2  :  1.8%us,  3.0%sy,  0.0%ni, 90.4%id,  0.0%wa,  0.0%hi,  1.2%si,  3.6%st
Cpu3  :  1.4%us,  2.7%sy,  0.0%ni, 91.2%id,  0.0%wa,  0.0%hi,  1.4%si,  3.4%st
Cpu4  :  0.9%us,  0.9%sy,  0.0%ni, 96.7%id,  0.0%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu5  :  0.9%us,  1.4%sy,  0.0%ni, 95.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.9%st
Cpu6  :  2.3%us,  1.8%sy,  0.0%ni, 94.6%id,  0.0%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu7  :  0.9%us,  1.9%sy,  0.0%ni, 95.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.4%st
Cpu8  :  0.8%us,  0.8%sy,  0.0%ni, 97.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu9  :  1.2%us,  0.8%sy,  0.0%ni, 96.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu10 :  0.8%us,  0.8%sy,  0.0%ni, 97.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu11 :  1.2%us,  0.8%sy,  0.0%ni, 96.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu12 :  1.7%us,  1.3%sy,  0.0%ni, 95.8%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu13 :  0.4%us,  0.8%sy,  0.0%ni, 97.5%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu14 :  0.8%us,  0.8%sy,  0.0%ni, 97.1%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu15 :  1.2%us,  1.2%sy,  0.0%ni, 96.3%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu16 :  2.1%us,  2.5%sy,  0.0%ni, 94.2%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu17 :  0.4%us,  1.7%sy,  0.0%ni, 97.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu18 :  3.3%us,  1.2%sy,  0.0%ni, 94.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu19 :  0.8%us,  0.8%sy,  0.0%ni, 97.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.8%st
Cpu20 :  0.8%us,  0.8%sy,  0.0%ni, 97.1%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu21 :  2.1%us,  0.9%sy,  0.0%ni, 95.7%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu22 :  0.8%us,  1.7%sy,  0.0%ni, 96.2%id,  0.0%wa,  0.0%hi,  0.0%si,  1.3%st
Cpu23 :  1.6%us,  0.8%sy,  0.0%ni, 96.3%id,  0.0%wa,  0.0%hi,  0.0%si,  1.2%st
Cpu24 :  0.4%us,  0.4%sy,  0.0%ni, 97.7%id,  0.0%wa,  0.0%hi,  0.0%si,  1.6%st
Cpu25 :  0.0%us,  0.4%sy,  0.0%ni, 97.3%id,  0.0%wa,  0.0%hi,  0.0%si,  2.4%st
Cpu26 :  0.4%us,  0.0%sy,  0.0%ni, 97.9%id,  0.0%wa,  0.0%hi,  0.0%si,  1.7%st
Cpu27 :  0.0%us,  0.0%sy,  0.0%ni, 98.4%id,  0.0%wa,  0.0%hi,  0.0%si,  1.6%st
Cpu28 :  9.1%us,  9.1%sy,  0.0%ni, 70.8%id,  0.0%wa,  0.0%hi,  9.7%si,  1.3%st
Cpu29 :  0.0%us,  0.4%sy,  0.0%ni, 98.0%id,  0.0%wa,  0.0%hi,  0.0%si,  1.6%st
Cpu30 :  0.0%us,  0.0%sy,  0.0%ni, 97.5%id,  0.0%wa,  0.0%hi,  0.0%si,  2.5%st
Cpu31 :  0.4%us,  0.0%sy,  0.0%ni, 97.5%id,  0.0%wa,  0.0%hi,  0.0%si,  2.1%st

Not much going on. Plenty of resources.

Yes, we followed the commendations in the referenced document. The biggest improvement, about 30%, was achieved by enabling RPS (echo f > /sys/class/net/eth0/queues/rx-0/rps_cpus).

kporter · June 3, 2016, 7:49pm

The wt_master_wait_prole is the time spent waiting on the replica write to succeed which relates directly to fabric-workers. Try increasing the fabric-workers from the default of 16 to 32 to match your cores.

vjk · June 3, 2016, 8:11pm

Kevin,

I already have 32:

service {
        user root
        group root
        paxos-single-replica-limit 1 # Number of nodes where the replica count is automatically reduced to 1.
        pidfile /var/run/aerospike/asd.pid
        service-threads 32
        transaction-queues 32
        transaction-threads-per-queue 3
        proto-fd-max 15000

kporter · June 6, 2016, 7:17pm

If you do have 32 for fabric-workers already then you managed to miss that line when copying ;).

Should look something like this:

service {
        user root
        group root
        paxos-single-replica-limit 1 # Number of nodes where the replica count is automatically reduced to 1.
        pidfile /var/run/aerospike/asd.pid
        service-threads 32
        transaction-queues 32
        transaction-threads-per-queue 3
        proto-fd-max 15000
        fabric-workers 32

vjk · June 6, 2016, 8:05pm

Yes, that’s exactly how it looks. Sorry, I did miss a line.

Now, that I thought about it, we actually suffer 8x performance slowdown due to 2x replication since a two node cluster provides 80K tps vs 320 tps for a one node cluster. Also, when I add node 3, the throughput goes up by about 40K tps. So, that’s about 40K tps per node and in order to catch up with one node no replication performance we would need 8 nodes giving us 8x40 = 320 K transactions/s.

kporter · June 7, 2016, 8:27pm

We do expect transitioning from 1 node to 2 nodes with replication factor two to be about 1/2 the performance of a single node due to the write amplification from replica writes.

Our performance lab is unaware of any change that would change our expectations so I have opened a ticket, AER-5061, to investigate this further.

Topic		Replies	Views
Extremely low TPS in distributed configuration -> XDR XDR (Cross Data Center Replication)	3	2459	January 16, 2015
Confusing benchmark results Aerospike Server Benchmarks	2	2721	June 22, 2015
Write performance in multi-node clusters? Operations	10	4556	May 1, 2015
Degradation of performance as clients increased Aerospike Server Benchmarks	4	3996	February 6, 2015
The TPS of Aerospike to insert sorted map	8	1240	June 6, 2017

Bad performance with replication

Related Topics