0007652: The idle process does not wake up when delays are scheduled, on linux

(0014155 - 524 - 548 - 548 - 548 - 548 - 548)
KenCausey
07-14-11 20:45
edited on: 07-14-11 20:45

I could be mistaken but this seems somehow related to an issue we have at least seen on source.squeak.org and I suspect affects many Squeak websites occasionally.

What we have seen is that source.squeak.org will stop responding. If one simply connects to the image via RFB (aka VNC) and wiggles the mouse the system begins responding again normally and may do so for many weeks before this comes up again. Actually it has been a while since we have seen this behavior I think, I'm not sure what changed (poor memory).

(0014156 - 285 - 303 - 303 - 303 - 303 - 303)
matthewf
07-14-11 21:13

I was able to work around the issue and have processes run at full speed by commenting out #interCyclePause: in WorldState >> doOneCycleFor:

However, this makes squeak run at full cpu all the time. I noticed that squeak runs at full cpu anyway when the mouse is moving. not sure why

(0014157 - 198 - 198 - 198 - 198 - 198 - 198)
matthewf
07-14-11 21:21

If I start an infinite loop in a low priority process some other way (ui process or otherwise), my network sender process runs at full speed. I guess allowing the idle process to run causes this bug

(0014158 - 354 - 354 - 354 - 354 - 354 - 354)
matthewf
07-14-11 21:53

The maximum frequency the delay will run at normally is independent of the morphic event loop; the number 50fps seems to be a mere coincidence, as that is the default frequency the morphic event loop runs at. If I set the morphic event loop to wait 1 millisecond or 2000 milliseconds between runs, my delay will never wakeup more than 50 times per second

(0014159 - 226 - 238 - 238 - 238 - 238 - 238)
matthewf
07-14-11 22:09
edited on: 07-14-11 22:10

The delay wakeup cap seems to actually be 60fps; it sometimes wakes up as many as 58.5 times per second if the processor is idling, but no more. This makes me suspect the VM relinquishPhysicalProcessor code or the Delay code

(0014160 - 4641 - 10584 - 10584 - 10584 - 10584 - 10584)
craig
07-14-11 22:32

Shouldn't the relinquish-processor primitive (230) make the next delay wakeup tick the most important consideration? Something like...

void relinquishPhysicalProcessor(void) {
        /* relinquishPhysicalProcessor */

        /* the next delay wakeup time */
        int nextWakeupTick = vm->getNextWakeupTick();

        int now = (vm->ioMicroMSecs() & 0x1fffffff);
        int timeoutInMilliseconds;
#ifdef UNIXISH
        struct timeval currentTime;
        struct timespec wakeupTime;
#endif

        if (nextWakeupTick <= now) {
                if (nextWakeupTick == 0)
                        /*
                         * Timer interrupts have been disabled; wait
                         * for as long as possible before anyone might
                         * notice. Specifically, wait for one frame
                         * at a typical GUI frame rate (60 Hz).
                         */
                        timeoutInMilliseconds = (1000/60);
                else
                        /*
                         * The next delay wakeup time has passed and
                         * the system should resume as soon as
                         * possible.
                         */
                        timeoutInMilliseconds = 0;}
        else
                timeoutInMilliseconds = nextWakeupTick - now;

#ifdef UNIXISH
        pthread_mutex_lock(&activity.mutex);
        gettimeofday(&currentTime, NULL);
        wakeupTime.tv_nsec = (currentTime.tv_usec * 1000) + (timeoutInMilliseconds * 1000000);
        wakeupTime.tv_sec = currentTime.tv_sec + (wakeupTime.tv_nsec / 1000000000);
        wakeupTime.tv_nsec %= 1000000000;

        pthread_cond_timedwait(
                &activity.request,
                &activity.mutex,
                &wakeupTime);

        pthread_mutex_unlock(&activity.mutex);
#endif
        vm->setInterruptCheckCounter(0);}

(0014161 - 927 - 1035 - 1035 - 1035 - 1035 - 1035)
matthewf
07-14-11 23:06
edited on: 07-14-11 23:07

Here is a chunk of code you can evaluate in a workspace to see how often a delay is triggering. It should be triggering about 1000 times per second, but is actually triggering 30-40 times per second on my machine when idle, or 170-180 times per second when I keep the mouse in constant motion

| tally delay morph updateDelay |
tally := 0. delay := Delay forMilliseconds: 1.
updateDelay := Delay forMilliseconds: 1000.
morph := TextMorph new openInWorld.
[[tally := tally + 1. delay wait] repeat] forkAt: 44.
[[morph contents: tally printString. tally := 0. updateDelay wait] repeat] forkAt: 45.

(to stop the code, kill processes of priority 44, 45, and 35 in the process browser, and delete the morph)

If I start a low priority infinite loop to completely starve the idle process, the delay wakes up 995-998 times per second, which is good:

[[] repeat] forkAt: 35

Except that we like running at low cpu

(0014162 - 130 - 130 - 130 - 130 - 130 - 130)
craig
07-14-11 23:12

I tried your workspace code with a VM that uses my relinquish primitive. It's near 1000 all the time, whether I use the UI or not.

(0014163 - 132 - 132 - 326 - 326 - 326 - 326)
KenCausey
07-15-11 19:13

This issue is also being discussed on the vm-dev list. See http://lists.squeakfoundation.org/pipermail/vm-dev/2011-July/008811.html [^]

Issue History
Date Modified	Username	Field	Change
07-14-11 19:47	matthewf	New Issue
07-14-11 20:45	KenCausey	Note Added: 0014155
07-14-11 20:45	KenCausey	Note Edited: 0014155
07-14-11 21:13	matthewf	Note Added: 0014156
07-14-11 21:21	matthewf	Note Added: 0014157
07-14-11 21:27	matthewf	Summary	Morphic interferes with process scheduling => The idle process does not wake up more often than once per 20 milliseconds on linux
07-14-11 21:28	matthewf	Category	Morphic => Kernel
07-14-11 21:53	matthewf	Note Added: 0014158
07-14-11 22:09	matthewf	Note Added: 0014159
07-14-11 22:10	matthewf	Note Edited: 0014159
07-14-11 22:32	craig	Note Added: 0014160
07-14-11 23:06	matthewf	Note Added: 0014161
07-14-11 23:06	matthewf	Note Edited: 0014161
07-14-11 23:07	matthewf	Note Edited: 0014161
07-14-11 23:12	craig	Note Added: 0014162
07-14-11 23:20	matthewf	Summary	The idle process does not wake up more often than once per 20 milliseconds on linux => The idle process does not wake up when delays are scheduled, on linux
07-14-11 23:20	matthewf	Additional Information Updated
07-14-11 23:23	matthewf	Category	Kernel => VM
07-15-11 19:13	KenCausey	Note Added: 0014163
08-09-11 01:35	lewis	Issue Monitored: lewis
01-06-14 18:18	lewis	Status	new => assigned
01-06-14 18:18	lewis	Assigned To	=> lewis

Notes
(0014155 - 524 - 548 - 548 - 548 - 548 - 548) KenCausey 07-14-11 20:45 edited on: 07-14-11 20:45	I could be mistaken but this seems somehow related to an issue we have at least seen on source.squeak.org and I suspect affects many Squeak websites occasionally. What we have seen is that source.squeak.org will stop responding. If one simply connects to the image via RFB (aka VNC) and wiggles the mouse the system begins responding again normally and may do so for many weeks before this comes up again. Actually it has been a while since we have seen this behavior I think, I'm not sure what changed (poor memory).

(0014156 - 285 - 303 - 303 - 303 - 303 - 303) matthewf 07-14-11 21:13	I was able to work around the issue and have processes run at full speed by commenting out #interCyclePause: in WorldState >> doOneCycleFor: However, this makes squeak run at full cpu all the time. I noticed that squeak runs at full cpu anyway when the mouse is moving. not sure why

(0014157 - 198 - 198 - 198 - 198 - 198 - 198) matthewf 07-14-11 21:21	If I start an infinite loop in a low priority process some other way (ui process or otherwise), my network sender process runs at full speed. I guess allowing the idle process to run causes this bug

(0014158 - 354 - 354 - 354 - 354 - 354 - 354) matthewf 07-14-11 21:53	The maximum frequency the delay will run at normally is independent of the morphic event loop; the number 50fps seems to be a mere coincidence, as that is the default frequency the morphic event loop runs at. If I set the morphic event loop to wait 1 millisecond or 2000 milliseconds between runs, my delay will never wakeup more than 50 times per second

(0014159 - 226 - 238 - 238 - 238 - 238 - 238) matthewf 07-14-11 22:09 edited on: 07-14-11 22:10	The delay wakeup cap seems to actually be 60fps; it sometimes wakes up as many as 58.5 times per second if the processor is idling, but no more. This makes me suspect the VM relinquishPhysicalProcessor code or the Delay code

(0014160 - 4641 - 10584 - 10584 - 10584 - 10584 - 10584) craig 07-14-11 22:32	Shouldn't the relinquish-processor primitive (230) make the next delay wakeup tick the most important consideration? Something like... void relinquishPhysicalProcessor(void) { /* relinquishPhysicalProcessor / / the next delay wakeup time / int nextWakeupTick = vm->getNextWakeupTick(); int now = (vm->ioMicroMSecs() & 0x1fffffff); int timeoutInMilliseconds; #ifdef UNIXISH struct timeval currentTime; struct timespec wakeupTime; #endif if (nextWakeupTick <= now) { if (nextWakeupTick == 0) / * Timer interrupts have been disabled; wait * for as long as possible before anyone might * notice. Specifically, wait for one frame * at a typical GUI frame rate (60 Hz). / timeoutInMilliseconds = (1000/60); else / * The next delay wakeup time has passed and * the system should resume as soon as * possible. / timeoutInMilliseconds = 0;} else timeoutInMilliseconds = nextWakeupTick - now; #ifdef UNIXISH pthread_mutex_lock(&activity.mutex); gettimeofday(&currentTime, NULL); wakeupTime.tv_nsec = (currentTime.tv_usec 1000) + (timeoutInMilliseconds * 1000000); wakeupTime.tv_sec = currentTime.tv_sec + (wakeupTime.tv_nsec / 1000000000); wakeupTime.tv_nsec %= 1000000000; pthread_cond_timedwait( &activity.request, &activity.mutex, &wakeupTime); pthread_mutex_unlock(&activity.mutex); #endif vm->setInterruptCheckCounter(0);}

(0014161 - 927 - 1035 - 1035 - 1035 - 1035 - 1035) matthewf 07-14-11 23:06 edited on: 07-14-11 23:07	Here is a chunk of code you can evaluate in a workspace to see how often a delay is triggering. It should be triggering about 1000 times per second, but is actually triggering 30-40 times per second on my machine when idle, or 170-180 times per second when I keep the mouse in constant motion \| tally delay morph updateDelay \| tally := 0. delay := Delay forMilliseconds: 1. updateDelay := Delay forMilliseconds: 1000. morph := TextMorph new openInWorld. [[tally := tally + 1. delay wait] repeat] forkAt: 44. [[morph contents: tally printString. tally := 0. updateDelay wait] repeat] forkAt: 45. (to stop the code, kill processes of priority 44, 45, and 35 in the process browser, and delete the morph) If I start a low priority infinite loop to completely starve the idle process, the delay wakes up 995-998 times per second, which is good: [[] repeat] forkAt: 35 Except that we like running at low cpu

(0014162 - 130 - 130 - 130 - 130 - 130 - 130) craig 07-14-11 23:12	I tried your workspace code with a VM that uses my relinquish primitive. It's near 1000 all the time, whether I use the UI or not.

(0014163 - 132 - 132 - 326 - 326 - 326 - 326) KenCausey 07-15-11 19:13	This issue is also being discussed on the vm-dev list. See http://lists.squeakfoundation.org/pipermail/vm-dev/2011-July/008811.html [^]

Relationships