GPU vs CPU vs AVX

Vector databases are all the rage. So, I looked at three different ways of multiplying vectors: CPU, GPU and Advanced Vector Extensions that leverages SIMD instructions if your hardware supports them. To access the GPU, I'm using the Tornado Java VM. For AVX, I'm using the JVM's jdk.incubator.vector module, available since JDK16.

(Code in my GitHub repo here).

The reason we're looking at vector mulitplication is that searching for vectors (what the vector DB is all about) usually uses something like the approximate nearest neighbour algorithm. One way to implement it is something like Ethan Lui's implementation mentioned in a past blogpost here. Briefly: it multiplies your vector by random vectors resulting in a vector whose bits are on or off depending on the sign of each element in the product.

The results are as follow (note, the GPU is a Quadro T2000 that apparently has 4gb of memory, 1024 cores and a bandwidth of 128 gigabits per second).

You can see that there is a huge fixed cost to using the GPU but once you get sufficiently large vectors, it's worth it. But what causes this fixed cost?

On my Intel Xeon E-2286M  CPU @ 2.40GHz, kernel calls take typically 17.8ns.

  17.776 ±(99.9%) 0.229 ns/op [Average]

  (min, avg, max) = (17.462, 17.776, 19.040), stdev = 0.306

  CI (99.9%): [17.547, 18.005] (assumes normal distribution)

JNI calls take a little longer at about 21.9ns:

  21.853 ±(99.9%) 0.488 ns/op [Average]

  (min, avg, max) = (21.345, 21.853, 23.254), stdev = 0.651

  CI (99.9%): [21.365, 22.340] (assumes normal distribution)

So, it doesn't seem that the fixed costs incurred in the GPU vector multiplication is due to context switching when calling the kernel or calls via JNI.

Note the maximum vector size for this test was 8 388 608 floats. 

That's 268 435 456 bits or 0.25 gigabits.

Based on just bandwidth alone and ignoring everything else, each call should be about 1.95ms. This matches the average observed time (1.94971ms). 

This suggests the actual calculation is incredibly fast and only the low bandwidth is slowing it down. Tornado VM appears to have minimal room for improvement - you really are getting the best you can out of the hardware.

Spark: checkpoint or cache?

Previously, 20k sentences would take a few minutes using Spark's built-in machine learning algorithms. So, I was surprised that 20k larger documents could take far, far longer.

Note: each data-point was reduced to a vector of length 20 irrespective of whether it was a short sentence or a long piece of text. So document size should have been irrelevant.

After over three hours, my One-vs-All, Support Vector Machine still was not finished.

I managed to fix the problem but first, here are the results for the models I used on the larger documents. Again, the figures are indicative as I did not run the models more than once.

Model	Accuracy (%)
LogisticRegression	96.1
MultilayerPerceptronClassifier	96.0
NaiveBayes	90.7
RandomForestClassifier	85.2
LinearSVC and OneVsRest	74.2

Despite calling .cache() on every DataFrame in sight and everything apparently fitting into memory with gigabytes to spare, performance was dreadful. (Note that DataSet.cache has a default StorageLevel of MEMORY_AND_DISK whereas RDD.cache defaults to MEMORY_ONLY).

Using jstat, it was clear all the executor threads were involved in some sort of serialization with deep stack-frames in java.io.ObjectInputStream.

So, instead I tried calling checkpoint on the DataFrame before passing it to the machine learning algorithm. This has the effect of removing all lineage and writing to the HDFS directory you must set in sc.setCheckpointDir.

"Broadly speaking, we advise persisting when jobs are slow and checkpointing when they are failing" [1] say Karau and Warren but since my job was so slow it might as well have failed I had nothing to lose.

Indeed, the SVM was now able to process the data in a few minutes. Quite why cacheing didn't work as expected is something of a mystery that I will look at in another post.

[1] High Performance Spark

New to Java 8: Adders

I was reading this blog and played with the suite that tests how fast read/writes to a long are and I came across a class new to JDK 1.8, LongAdder.

(The test suite has a problem that the class that uses optimistic locking and a StampedLock ignores whether it has attained the lock but I'll deal with that elsewhere).

It's quite a cunning idea. If there is contention on the field containing the long value, the thread that fails to attain the lock creates a new memory location (a Striped64.Cell object) and adds its values there. When it comes to seeing the results of many threads mutating the value, the reader thread returns not just the base value but all values in the additional memory. Thus contention is minimized.

There is a caveat when it comes to adding up all the additional values. From the JavaDoc:

The returned value is NOT an atomic snapshot; invocation in the absence of concurrent updates returns an accurate result, but concurrent updates that occur while the sum is being calculated might not be incorporated.

Anyway, I updated the suite mentioned above adding a modified optimistic locking class that retries in the event not attaining the lock (OPTIMISTIC_CORRECT in the diagram below). The logs output look like this:

name,threads,duration
ADDER,16,782
ADDER,16,810
ADDER,16,769
ADDER,16,792
ADDER,16,771
ADDER,16,793
ADDER,16,735
ADDER,16,777
ADDER,16,768
ADDER,16,849
ATOMIC,16,514

.

.

and wrote some R code to process it and give me a graphic of all the different techniques:

.libPaths("/home/henryp/R/x86_64-unknown-linux-gnu-library/3.1/")
require("epade")
data            <- read.csv("/home/henryp/Code/R/JavaLocks/firstPastPost1W15R.csv")

groupBy         <- list(data$name, data$threads)
aggregatedMeans <-aggregate(data,
                            by=groupBy,
                            FUN=mean,
                            na.rm=TRUE)
aggregatedSds   <- aggregate(data,
                             by=groupBy,
                             FUN=sd,
                             na.rm=TRUE)

meansAndSds     <- cbind(aggregatedMeans[,c(1,5)],
                         aggregatedSds[,5])

ordered         <- meansAndSds[order(meansAndSds[,2]),]

bar3d.ade(data.matrix(ordered[,2],
                      rownames.force = NA),
          main="10000000 reads of a montonically incrementing long",
          y=ordered[,1],
          zticks=ordered[,1],
          xticks="1 writer, 15 readers",
          ylab="Duration (ms)")

The means and standard deviations look like this:

> ordered

             Group.1 duration aggregatedSds[, 5]

3              DIRTY    211.9           11.95780

2             ATOMIC    594.2           71.89777

9           VOLATILE    641.0           72.22188

1              ADDER    708.7           73.71122

5 OPTIMISTIC_CORRECT   1379.3          141.92334

4         OPTIMISTIC   7518.0         1392.87967

8       SYNCHRONIZED   8682.4         1507.51283

6             RWLOCK  10515.4          665.83251

7            STAMPED  21859.3         5076.10047

or, graphically:

Note: this has one writing thread and 15 reading threads on a 16 core (using hyperthreading) CPU. DIRTY means there was no locking, the fastest but least accurate technique. Duration (the vertical axis) is in milliseconds. I don't know why this axis is not labelled when I save the image as it is displayed in RStudio.

So, ADDER is indeed fast but not as fast as ATOMIC (which is also more accurate) on this computer and with this read/write profile. I'll try other numbers of readers and writers later.

The Performance of RSA Encryption

When encryption takes up a more of your round trip time than servicing the request itself, it's time to look at optimizing it.

I'm using a home-compiled version of OpenJDK that's running code that looks like this:

import static javax.crypto.Cipher.ENCRYPT_MODE;
        
        KeyPair             keyPair             = keyPairGenerator.genKeyPair();
        PrivateKey          privateKey          = keyPair.getPrivate();
        PublicKey           publicKey           = keyPair.getPublic();
        Cipher              cipher              = Cipher.getInstance(algorithm);
        
        // Note that privateKey is of type sun.security.rsa.RSAPrivateCrtKeyImpl
        
        cipher.init(ENCRYPT_MODE, privateKey);
        byte[] input = "hello world".getBytes();
        byte[] output = cipher.doFinal(input);

Stepping through the code

Thread [main] (Suspended)
RSACore.rsa(byte[], RSAPrivateKey) line: 101
RSACipher.doFinal() line: 352
RSACipher.engineDoFinal(byte[], int, int) line: 389
Cipher.doFinal(byte[]) line: 2121
.
.

I come to this in sun.security.rsa.RSACore:

    public static byte[] rsa(byte[] msg, RSAPrivateKey key)

            throws BadPaddingException {

        if (key instanceof RSAPrivateCrtKey) {

            return crtCrypt(msg, (RSAPrivateCrtKey)key);

        } else {

            return crypt(msg, key.getModulus(), key.getPrivateExponent());

        }

    }

If I wanted the other branch to be taken, I could do something like this:

    RSAPrivateKey       rsaPrivateKey   = (RSAPrivateKey)privateKey;

    RSAPrivateKeySpec   keySpec         = new RSAPrivateKeySpec(

        rsaPrivateKey.getModulus(), 

        rsaPrivateKey.getPrivateExponent());

    PrivateKey          slowPrivateKey  =

        KeyFactory.getInstance("RSA").generatePrivate(keySpec);

and call a Cipher that has been initialized with a private key of class sun.security.rsa.RSAPrivateKeyImpl rather than RSAPrivateCrtKeyImpl. Then when we get to the crypt method, we see this:

        BigInteger c = m.modPow(exp, n);

The BigInteger method modPow is very expensive since exp and n are enormous numbers. In fact, as I run jstack against my JVM, I see half a dozen threads in this code.

Conclusion

Because RSAPrivateCrtKey carries much more information than the interface RSAPrivateKey demands, less expensive calculations appear to be needed. Therefore, encryption is considerably faster using keys of this class than RSAPrivateKeyImpl.

When I benchmarked the two on a small string ("hello world") using JMH I found RSAPrivateCrtKey over three times faster when encrypting.

Lies, Damned Lies and Performance Statistics

A new way of measuring performance

I've introduced HdrHistogram to my pet project, JStringServer. The advantages of HdrHistogram is that it keeps the results in constant memory with constant access time. The only cost is some approximation of results and since I'm only interested in means, standard deviations etc I can live with that.

HdrHistogram works by keeping an array of "buckets" which represent a range of values. Any given value that falls into a particular bucket merely increases that bucket's counter. This is much more memory efficient than, say Apache's JMeter that keeps every reading in memory.

The range of these buckets grow exponentially (well, there are sub-buckets but let's keep this simple). So, all results that are outliers are collected in just one or two buckets. This is very memory efficient as each bucket is a Java long each.

Means, standard deviations and all that

Most performance tools like Apache's JMeter will give you a mean and a standard deviation. You might have even heard that 68% of results are within a standard deviation of the mean, 95% within 2 standard deviations, 99.7% within 3 etc (see here for the rule). But this is only true for a normal distribution (the typical, bell-shaped curve).

The time it takes for a given measurement independent of all others will typically conform to a Poisson distribution. (See Mathematical Methods in the Physical Sciences by Mary Boas for a clear derivation of this formula from first principles.)

Results

Typically, I see:

Initiated 412759 calls. Calls per second = 10275. number of errors at client side = 0. Average call time = 10ms
ThreadLocalStopWatch [name=read, totalCallsServiced=412659, max time = 630ms, Mean = 6.125236575477573, Min = 0, standard deviation 8.263969133274433, Histogram with stepsize = 1. Approximate values: 791, 1822, 3524, 15650, 143582, 307867, 243841, 81151, 18447, 4716, 1395, 493, 314, 195, 106, 97, 82, 66, 35, 10, 6, 7, 10, 7, 12, 14, 8, 7, 4, 2]
ThreadLocalStopWatch [name=write, totalCallsServiced=412719, max time = 26ms, Mean = 0.08618696982692825, Min = 0, standard deviation 0.327317028847167, Histogram with stepsize = 1. Approximate values: 411831, 33604, 771, 238, 80, 32, 17, 8, 1, 1, 2, 4, 5, 3, 0, 0, 1, 1, 1, 1, 0, 0, 1, 2, 5, 8, 4, 0, 0, 0]
ThreadLocalStopWatch [name=connect, totalCallsServiced=412720, max time = 3005ms, Mean = 4.17902209730568, Min = 0, standard deviation 65.54450133531354, Histogram with stepsize = 1. Approximate values: 408721, 117052, 2056, 852, 282, 114, 57, 30, 15, 12, 10, 10, 15, 10, 3, 5, 4, 3, 2, 1, 3, 4, 2, 0, 1, 1, 0, 1, 1, 0]
ThreadLocalStopWatch [name=total, totalCallsServiced=410682, max time = 66808064ns, Mean = 6295825.973268021, Min = 854104, standard deviation 1089344.7561186429, Histogram with stepsize = 1333333. Approximate values: 145, 837, 1596, 25512, 273990, 93021, 12099, 2283, 520, 273, 126, 77, 80, 55, 11, 9, 5, 9, 10, 11, 15, 5, 3, 2, 3, 3, 0, 0, 4, 1, 2]

For something that approximates to a Poisson distribution, we'd expect the mean and standard deviation to be about the same. Since this is not true for the total time, perhaps this is not a Poisson distribution. The results for reading data does have these two values roughly the same so let's look at them.

Let's see if the distribution of the values conform to the Poisson distribution or even the Normal (aka Gaussian). In the R language:

require(graphics)

# Histogram of times. Each interval is 1ms starting from 1ms
xread <- c(791, 1822, 3524, 15650, 143582, 307867, 243841, 81151, 18447, 4716, 1395, 493, 314, 195, 106, 97, 82, 66, 35, 10, 6, 7, 10, 7, 12, 14, 8, 7, 4, 2)
readMean = 6.125236575477573
readSd   = 8.263969133274433
readNum  = 412659

par(mfrow = c(3, 1)) # we're looking at 3 graphs

n      = readNum
x      = xread
mean   = readMean
sd     = readSd

ac <- barplot(x, main="Actual Distribution", axes=TRUE) 
axis(1, at=ac, labels=TRUE)

i <- 1:length(x)

expectedPoisson = n * dpois(i, lambda=mean)
expectedNorm    = n * dnorm(i, mean=mean, sd=sd)

nm <- barplot(expectedNorm, main="Expected Normal Distribution")
axis(1, at=nm, labels=TRUE)

pn <- barplot(expectedPoisson, main="Expected Poisson Distribution")
axis(1, at=pn, labels=TRUE)

chisq.test(x, p=expectedPoisson, rescale.p=TRUE)
chisq.test(x, p=expectedNorm,    rescale.p=TRUE)

The last two lines are testing whether the actual distribution conforms to the Poisson (give a lambda value) or a Normal (given the mean and the standard deviation). It does this using the chi-squared test (basically, a comparison of the squared differences between what we expect and what we get).

For these particular results, the p-value from the chi-squared tests tell me they neither conform to a Poisson not a Normal distribution (in fact, they could barely be further from them). Looking at the graphs, you can see this by-eye:

So, what went wrong? Well, the Poisson distribution relies on events being independent of each other which is clearly not the case when there is contention for resources.

The Central Limit Theorem

(Aside):

The means of a distribution form a normal distribution given enough runs even if that original distribution is not itself a normal distribution.

Let's look at plotting the Poisson distribution in R:

mu=1; sigma=10   # mean, standard deviation
n=5000           # Number of iterations
xbar=rep(0,n)    # Holds the results of the iterations

for (i in 1:n) { 
  xbar[i]=mean(
    rpois(5000, mu) # num. random variables = 5000, mu = means
    ) 
}

par(mfrow = c(2, 1))

# Plot a typical Poisson distribution
hist(rpois(n, mu),prob=TRUE,breaks=15)

# Plot the results of n Poisson distributions
hist(xbar,prob=TRUE) #,xlim=c(70,130),ylim=c(0,0.1))

Gives this result:

A typical Poisson distribution and the mean of a Poisson over many iterations

This is quite nice as it means that if you run performance tests repeatedly, your means will approach a Normal Distribution giving some predictive power over them.

CPU affinity and Performance

The Problem

I have a single-threaded application (my play-project, JStringServer, running BatchedServerMain) that is very CPU and IO heavy and I want to improve its performance and stop it from jittering.

By running htop, I notice that it jumps from CPU to CPU. One moment it's on CPU 6...

the next, it's on CPU 11:

The number of serviced clients per second is all over the place (a mean of 9523 per second and a standard deviation of 864. Compare this with the results below).

The Solution

You might have read a lot about CPU affinity on the blogosphere (such as HighScalability and Mechanical Sympathy). Jumping between CPUs can be expensive and one tactic is to avoid it. Could it help me?

I've heard of proposals to allow this to be done within Java but there is nothing I know of that allows you to do it yet so I will have to do it via the OS.

CPU Affinity

You can pin processes to given CPUs quite easily on Linux (see this article for instructions). But which do we pin it to? Not all are the same...

I pin my process to each CPU and take timings by hitting the process from another box. These are the results I get measuring the number of clients serviced each second:

0 : mean =  10244.200 std dev =     47.298
1 : mean =  10253.600 std dev =     52.063
2 : mean =  10245.400 std dev =     48.202
3 : mean =  10204.800 std dev =     47.422
4 : mean =  10265.000 std dev =     54.902
5 : mean =   7807.400 std dev =     41.105
6 : mean =  10217.400 std dev =     51.623
7 : mean =  10274.000 std dev =     46.656
8 : mean =  10238.600 std dev =     62.919
9 : mean =  10290.600 std dev =     49.318
10 : mean =  10209.400 std dev =     52.044
11 : mean =  10194.800 std dev =     54.377
12 : mean =  10243.400 std dev =     52.321
13 : mean =   8874.000 std dev =     43.959
14 : mean =   9849.200 std dev =     49.794
15 : mean =  10352.000 std dev =     55.194

Hmm, three CPUs are slow, but especially CPU #5.

Let's look at my system. I'm using an Intel Xeon processor (E5-2687W) which has 8 cores and 16 hardware threads.

[henryp@corsair ~]$ numactl -H
available: 1 nodes (0)
node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
node 0 size: 65480 MB
node 0 free: 60931 MB
node distances:
node   0
  0:  10

This shows I have only one CPU and memory nodes so I don't have to worry about cross-socket NUMA problems (This is a good article about looking at NUMA and hardware).

OK, so what are all my CPUs in my socket doing?

[henryp@corsair 9dev]$ cat /proc/interrupts
            CPU0       CPU1       CPU2       CPU3       CPU4       CPU5       CPU6       CPU7       CPU8       CPU9       CPU10      CPU11      CPU12      CPU13      CPU14      CPU15      
   0:        171          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-edge      timer
   1:       3644          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-edge      i8042
   4:          2          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-edge    
   8:          1          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-edge      rtc0
   9:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   acpi
  12:     132544          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-edge      i8042
  17:          1          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   firewire_ohci
  23:         61          0          0          0          0          0         21          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   ehci_hcd:usb1, ehci_hcd:usb2
  27:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   ath9k
  32:     207183          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   nvidia
  36:        179          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IO-APIC-fasteoi   snd_hda_intel
  64:      27439      25657      81300          0       6288      32731       5618      45423          0          0          0          0          0          0          0          0   PCI-MSI-edge      ahci
  65:          5          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      ahci
  66:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  67:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  68:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  69:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  70:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  71:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  72:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  73:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  74:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  75:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  76:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  77:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  78:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  79:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  80:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  81:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      xhci_hcd
  82:         10          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      mei
  83:       1576          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      em1
  84:        757          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      snd_hda_intel
  85:         14          0          0          0          0     424447          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      p7p1-rx-0
  86:         19          0          0          0          0          0     216701          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      p7p1-tx-0
  87:          2          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   PCI-MSI-edge      p7p1
 NMI:        332        254        231        207        211        310        218        219        403        303        194        228        280        382        329        281   Non-maskable interrupts
 LOC:     418851     409978     386151     360594     358830     438636     351885     362193     292543     243019     179805     188224     223758     283426     257005     225531   Local timer interrupts
 SPU:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Spurious interrupts
 PMI:        332        254        231        207        211        310        218        219        403        303        194        228        280        382        329        281   Performance monitoring interrupts
 IWI:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   IRQ work interrupts
 RTR:         15          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   APIC ICR read retries
 RES:    1069726      92676      20752       8650       5003       4081       3523       2631       2234       2171       2467       1658       1974       1873       1849       1668   Rescheduling interrupts
 CAL:      53667      72109      69200      68746      62293      82125      72462      71374      49909      51974      52292      54965      55904      52059      54509      54112   Function call interrupts
 TLB:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   TLB shootdowns
 TRM:          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   Threshold APIC interrupts
 MCE:          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0          0   Machine check exceptions
 MCP:         12         12         12         12         12         12         12         12         12         12         12         12         12         12         12         12   Machine check polls
 ERR:          0
 MIS:          0

(Read this page to see how best to read this output).

CPU #5 seems to be handling an awful lot of interrupts from the network interface controller [NIC] for p7p1 (the name of my interface that the client is hitting).

"Unfortunately the default is to let all processors handle interrupts with the result that the overall performance is not optimal in particular on multi-core systems. This is because modern NICs can have multiple RX queues that work perfectly if cache coherency is respected. This means that interrupts for ethX-RX queue Y must be sent to 1 (one) core or at most to a core and its Hyper-Threaded (HT) companion. If multiple processors handle the same RX queue, this invalidates the cache and performance gets worse. For this reason IRQ balancing is the key for performance." [1]

OK, let's balance that puppy.

[root@corsair ~]# echo 15 > /proc/irq/85/smp_affinity ; echo 15 > /proc/irq/85/smp_affinity_list 

This works for a few seconds and I see the same throughput levels as the other CPUs but then my Fedora 17 reverts it! How annoying. It doesn't do that on my Ubuntu 12.04 (admittedly on different hardware).

So, I use Tuna to see what's going on. This is how it looks before the test:

And during:

We can see CPU #5 is handling a lot of kernel interrupts.

Conclusion

It seems that this particular CPU is busy handling network IO and making my process perform badly if I pin it to it. This is probably a reason for the jitter as the kernel sometimes schedules my process to run on it.

But at the moment, I don't know how to stop the kernel from disabling network interrupts on this CPU. So, I'll just avoid it in the future.

[1] http://www.ntop.org/pf_ring/irq-balancing/

Bufferbloat: less is more

You would have thought that increasing buffer sizes was always a good thing, right? Wrong.

You would have thought that reducing load on a system would always make it faster, right? Also wrong.

When stress testing our code in an Oracle lab in Edinburgh, we noticed that increasing the load on the system increased throughput. Independently, on totally different software (nothing in common other than it's written in Java and some of it's running on Linux) I saw the same thing on my home network.

In both cases, a large network buffer size and low load was the problem. At home, I saw this:

Initiated 7855 calls. Calls per second = 846. number of errors at client side = 0. Average call time = 81ms

Initiated 9399 calls. Calls per second = 772. number of errors at client side = 0. Average call time = 89ms

Initiated 10815 calls. Calls per second = 708. number of errors at client side = 0. Average call time = 96ms

.

.

etc until I started a second machine hitting the same single-threaded process whereupon performance shot up:

Initiated 18913 calls. Calls per second = 771. number of errors at client side = 0. Average call time = 107ms

Initiated 21268 calls. Calls per second = 1177. number of errors at client side = 0. Average call time = 105ms

Initiated 24502 calls. Calls per second = 1617. number of errors at client side = 0. Average call time = 99ms

Initiated 29802 calls. Calls per second = 2650. number of errors at client side = 0. Average call time = 88ms

Initiated 34192 calls. Calls per second = 2195. number of errors at client side = 0. Average call time = 82ms

Initiated 39558 calls. Calls per second = 2683. number of errors at client side = 0. Average call time = 77ms

How odd - more load on the server means better throughput.

I was browsing the subject of bufferbloat on various websites including Jim Getty's excellent blog [1] where he writes extensively on the topic. He says:

"... bloat occurs in multiple places in an OS stack (and applications!). If your OS TCP implementation fills transmit queues more than needed, full queues will cause the RTT to increase, etc. , causing TCP to misbehave."

Inspired by this, I added to my code:

        serverSocketChannel.setOption(
            SO_RCVBUF,
            4096);

before binding the channel to an address and the problem went away (the default value for this option was about 128kb on my Linux box).

Note that although this looks like a very small number, there is no fear of a buffer overrun.

"The TCP socket received buffer cannot overflow because the peer is not allowed is not allowed to send data beyond the advertised window. This is TCP's flow control" [2].

Curious to see why reducing the buffer size helps things, I tried sizes of 512, 1024, 2048 and so on until 65536 bytes while running

sudo tcpdump -nn -i p7p1 '(tcp[13] & 0xc0 != 0)'

which according to [3] should show me when the network experiences congestion (p7p1 is the name of my network interface, by the way).

The first value for SO_RCVBUF at which poor initial performance is encountered was 8192 bytes. Interestingly, as soon as the second client started hitting the server, tcpdump started spewing output like:

17:54:28.620932 IP 192.168.1.91.59406 > 192.168.1.94.8888: Flags [.W], seq 133960115:133961563, ack 2988954847, win 33304, options [nop,nop,TS val 620089208 ecr 15423967], length 1448
17:54:28.621036 IP 192.168.1.91.59407 > 192.168.1.94.8888: Flags [.W], seq 4115302724:4115303748, ack 2823779942, win 33304, options [nop,nop,TS val 620089208 ecr 15423967], length 1024
17:54:28.623174 IP 192.168.1.65.51628 > 192.168.1.94.8888: Flags [.W], seq 1180366676:1180367700, ack 1925192901, win 8688, options [nop,nop,TS val 425774544 ecr 15423967], length 1024
17:54:28.911140 IP 192.168.1.91.56440 > 192.168.1.94.8888: Flags [.W], seq 2890777132:2890778156, ack 4156581585, win 33304, options [nop,nop,TS val 620089211 ecr 15424257], length 1024

What can we make of this? Well, it appears that the bigger the buffer, the longer a packet can stay in the receiver's queue as Getty informs us [1]. The longer it stays in the queue, the longer the round trip time (RTT). The longer the RTT, the worse the sender thinks the congestion is as it doesn't differentiate between time lost on the network and time stuck in a bloated stupid FIFO queue. (The RTT is used in determining the congestion [4])

Given a small buffer, the receiver will, at a much lower threshold, tell the sender not to transmit any more packets [2]. Thus the queue is smaller and less time is spent in it. As a result, the RTT is low and the sender believes the network to be congestion-free and is inclined to send more data.

Given a larger buffer but with greater competition for resources (from the second client), the available space in the buffer is reduced so it things look very similar to the client as described in the previous paragraph.

It appears that the Linux community are wise to this and have taken countermeasures [5].

[1] JG's Ramblings.
[2] Unix Network Programming, p58, Stevens et al, p207
[3] Wikipedia.
[4] RFC 5681.
[5] TCP Small Queues.

Double Trouble

I'm writing a maths library in my spare time for fun. I've only got around to matrices but already I am seeing interesting behaviour.

Primarily, my library needs to be fast so I use primitives. My first matrix implementation uses doubles and I'm testing performance by calculating cross products.

I'm using the Caliper microbenchmarking framework to performance test my code with methods that look a little like:

    public int timeMutable2DDoubleMatrixCross(int reps) {

        Mutable2DDoubleMatrix accumulator = null;
        for (int i = 0 ; i < reps ; i++) {
            accumulator = mutable2DDoubleMatrix.cross(mutable2DDoubleMatrix);
        }
        return accumulator == null ? 0 : accumulator.getWidth();
    }

On my machine*, I get a result of  1.299ms (standard deviation of 0.011ms) to run an iteration of my code.

But you know when I wrote other implementations for other primitive types, there was an awful lot of copy, paste and make a minor change going on. Bearing in mind the usual autoboxing caveats I've mentioned before, what if I just changed the interface to use Double but the implementation and the call site were using primitive doubles? Maybe then I could make the code more generic with no loss of performance.

No joy - we still get the overhead of autoboxing. Average call time is now 4.041ms (standard deviation of 0.040ms). The JVM is not going to be fooled.

Ah, well. I was half expecting that and it's still better than using BigDecimal (that was taking 68.354ms per call.)

But what was really interesting is that double was faster than long (typically 1.403ms per call, 0.013ms std dev). That blew out of the water my plan to use inflated longs and then right rotate them to give approximate answers, echoing Kronecker's assertion that "God made natural numbers; all else is the work of man".


This might be because floating point calculations are passed to the Floating Point Unit. "In most computers, floating point arithmetic is usually much slower than integer arithmetic, though on the Intel Pentium it is usually faster because the integer unit was not given the same care as the floating point unit." [1]

As ever, your mileage may vary (YMMV).

* A 1.8 GHz Intel Core i7 running Mac OS X 10.7.5 and using java version 1.6.0_41.

[1] http://mindprod.com/jgloss/floatingpoint.html

Additional reading:
 - interesting read on the history of floating points (http://www.intel.com/standards/floatingpoint.pdf).
 - stats for the i7 processor (http://elrond.informatik.tu-freiberg.de/papers/WorldComp2012/PDP2833.pdf)