Comment 425 for bug 620074

Created attachment 23618
Simple sleeper test case

As this bug occurs more permanent while working in an virtual machine or while using java and I still think, that's this is a process scheduler bug (or something related). Here another test case, which shows the suspected behaviour. As there are many system calls while using a virtual machine, I have tries to find an equal test. The test case just sleeps for 1µs and measures the time difference of the usleep operation. I am using such many of the usleep operations, as the problems does not occur deterministic and I tried to catch as many as possibly occurrences.

I have run this test case on three machines. The first one was a Core2 Duo with a first generation SDD (OCZ Core Series) with a poor write performance and on a Ubuntu kernel 2.6.31-14-generic. The partitions are block aligned. I have run this test, while my wife was using firefox. Every time, she was submitting something and firefox is using sqlite for writing the history, there was a high latency for the sleep test.

Timediff 7629094: 16.80ms Total: 61.12ms
Timediff 7629100: 18.82ms Total: 93.68ms
Timediff 7629101: 19.96ms Total: 113.54ms
Timediff 7629102: 19.98ms Total: 133.43ms
Timediff 7629103: 19.97ms Total: 153.31ms
Timediff 7629104: 20.00ms Total: 173.24ms
Timediff 7629105: 19.96ms Total: 193.09ms
Timediff 7629106: 20.02ms Total: 213.02ms
Timediff 7629107: 19.94ms Total: 232.86ms
Timediff 7636162: 16.40ms Total: 34.44ms
Timediff 7636164: 19.90ms Total: 64.00ms

While the duration of 100 usleep should be somewhere between 10ms and 20ms, 10 usleep(1) takes more than 200ms. This behaviour is reproducible.

On my machine, a Core2Duo, a normal 2.5" hard drive with a vanilla kernel 2.6.31.5, there is an equal behaviour. While making a backup from one hard drive to another, the latency jumps to >30ms for one usleep(1) nearby every second. But there are some latencies grater than >150ms for one usleep(1).

Timediff 11054523: 38.23ms Total: 53.19ms
Timediff 11212737: 21.64ms Total: 31.46ms
Timediff 11213557: 35.59ms Total: 44.62ms
Timediff 11213939: 59.88ms Total: 65.76ms
Timediff 11264190: 40.83ms Total: 49.72ms
Timediff 11264709: 53.77ms Total: 63.09ms
Timediff 11265629: 145.74ms Total: 155.96ms
Timediff 11327458: 16.94ms Total: 25.23ms
Timediff 11376430: 18.91ms Total: 27.67ms
Timediff 11408941: 17.67ms Total: 26.36ms
Timediff 11424964: 19.26ms Total: 28.01ms
Timediff 11509722: 19.84ms Total: 28.30ms
Timediff 11627259: 27.01ms Total: 34.51ms
Timediff 11645718: 18.26ms Total: 29.80ms

On my server Athlon X2 on a full encrypted RAID-5 with lvm on a 2.6.18-128.2.1.el5.028stab064.7 (CentOS with OpenVZ) kernel, the behaviour was even worse. While copying a 4GB iso, there are latencies of one usleep(1) up to one second.

Timediff 40397: 24.16ms Total: 122.93ms
Timediff 40417: 859.04ms Total: 981.78ms
Total 40417: 981.78ms
Timediff 45928: 22.62ms Total: 220.16ms
Timediff 50471: 25.02ms Total: 135.80ms
Timediff 51085: 19.23ms Total: 163.03ms
Timediff 51097: 205.12ms Total: 360.66ms
Timediff 51160: 47.47ms Total: 422.81ms
Total 51160: 422.81ms
Timediff 51662: 21.93ms Total: 279.08ms
Timediff 51663: 40.87ms Total: 318.58ms
Total 52068: 401.49ms
Timediff 54540: 16.69ms Total: 150.93ms
Timediff 63056: 78.07ms Total: 203.86ms
Timediff 65673: 16.43ms Total: 228.44ms
Timediff 65675: 24.04ms Total: 265.11ms

On all three machines, there were small latencies without any fsync or copy operation. On the machines with the Core2Duo and kernel 2.6.31 the latencies are below 0.2ms and 0.1ms, even while watching a movie or using 100% of the cpu. On the Athlon X2 and the kernel 2.6.18, the latencies are always below 1ms.

A 200ms latency while moving the mouse is noticeable. A delay of 1 second, while moving the mouse, should be the freezes, which many of us notice during copy operations.

Why is the kernel delaying resume of the usleep(1) operation up to one second during a copy operation? Please have a look on this behaviour.