bugGNU Octave - Bugs: bug #55940, [Mac] Disable App Nap, either...

 
 

bug #55940: [Mac] Disable App Nap, either selectively or for all of Octave

Submitted by:  Andrew Janke <apjanke>
Submitted on:  Sun 17 Mar 2019 02:40:10 PM UTC  
 
Category:  None Severity:  3 - Normal
Priority:  5 - Normal Item Group:  Feature Request
Status:  Confirmed Assigned to:  None
Originator Name:  Open/Closed:  Open
Release:  dev Operating System:  Mac OS

Add a New Comment(Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

( Jump to the original submission)

Wed 22 May 2019 04:28:40 AM UTC, comment #45:

Disabling once at startup seems reasonable. After all, this was the behavior before 10.9 and Octave ran fine.

Rik <rik5>
Project Administrator
Wed 22 May 2019 04:08:14 AM UTC, comment #44:

And here's a reference to what I think is Apple's doco on the topic. It seems to match what's in that SO answer.

https://developer.apple.com/library/archive/documentation/Performance/Conceptual/power_efficiency_guidelines_osx/PrioritizeWorkAtTheAppLevel.html#//apple_ref/doc/uid/TP40013929-CH36-SW1.

Since Octave is a general-purpose programming language and analytics tool, it can't really know what user code might be "low priority" (and from my experience with M-code, it's unlikely that any of it would be). So it should probably disable App Nap/declare a "high priority" activity whenever it's executing any M-code or running a user-defined timer.

So Octave could probably do a `beginActivityWithOptions:reason:` as soon as the interpreter is asked to run something, and whenever timers are active. If that's not convenient to implement, I'd think it would be fine to just disable App Nap once on Octave startup, and just leave it disabled for the process lifetime. There's no reason to expect Octave to be optimized for App Nap support.

I don't think I could do the patch that disables App Nap just while in the interpreter, but I think I could put one together for disabling it for the entire Octave process lifetime.

Andrew Janke <apjanke>
Tue 21 May 2019 06:45:40 PM UTC, comment #43:

Here is a SO item about nanosleep taking 10 seconds, with some answers that may help someone write a patch for Octave to call the appropriate system API calls to disable App Nap, either in critical sections of code, or every time Octave starts, or by calling a new Octave built-in or oct-file.

https://stackoverflow.com/q/22784886/384593

Mike Miller <mtmiller>
Project Administrator
Tue 21 May 2019 06:23:00 PM UTC, comment #42:

It's actually been discussed here before, but it only occurred to me today. I remembered that macOS has a dynamic scheduling power saving feature, and a few minutes of googling found the right name.

See bug #46845 for the previous report about the same exact problem from 3 years ago that we all forgot about.

Now I've seen some references to this being something that users have to disable each time an application runs, but also a reference to an API call that an application can use to disable it internally. If there is such a call that Octave can use, and that's desirable to do, either unconditionally or with an Octave setting, I'm sure we would apply such a patch.

Mike Miller <mtmiller>
Project Administrator
Tue 21 May 2019 06:07:15 PM UTC, comment #41:

Wow, nice shot in the dark Mike.

Can we close this report as invalid since this is way upstream of Octave?

Rik <rik5>
Project Administrator
Tue 21 May 2019 05:53:42 PM UTC, comment #40:

> Is this the macOS App Nap feature kicking in after Octave has been mostly idle for about 20-30 seconds?


It is! In fact, it's kicking in way sooner than that. I can see the "App Nap" = "Yes" in Activity Monitor for my Octave process.

If I plot a figure, that turns off the App Nap, and then pauses are fast again.

And if I do the pause tests again and watch activity monitor, it sure seems like App Nap is kicking in right when the pauses become slow.

I believe we have a likely suspect.

Andrew Janke <apjanke>
Tue 21 May 2019 05:45:09 PM UTC, comment #39:

Is this the macOS App Nap feature kicking in after Octave has been mostly idle for about 20-30 seconds?

Mike Miller <mtmiller>
Project Administrator
Tue 21 May 2019 05:36:10 PM UTC, comment #38:

Alright. Thanks for testing the various possibilities.

I'm out of ideas. It doesn't seem that Octave is doing anything that would cause this behavior.

Rik <rik5>
Project Administrator
Tue 21 May 2019 05:30:26 PM UTC, comment #37:

Behavior seems about the same with the new code. I built an Octave from the head of default, and the slow pause behavior still happens, kicking in after about 200 calls to pause().

$ octave-default -q -f
octave:1> ver
----------------------------------------------------------------------
GNU Octave Version: 6.0.0 (hg id: 5fa8d1459b35 + patches)
GNU Octave License: GNU General Public License
Operating System: Darwin 18.6.0 Darwin Kernel Version 18.6.0: Thu Apr 25 23:16:27 PDT 2019; root:xnu-4903.261.4~2/RELEASE_X86_64 x86_64
----------------------------------------------------------------------
Package Name | Version | Installation directory
--------------+---------+-----------------------
control | 3.1.0 | /Users/janke/octave/control-3.1.0
image | 2.8.1 | /Users/janke/octave/image-2.8.1
octave:2> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
0.104 0.105 0.102 0.105 0.102 0.104 0.104 0.104 0.102 0.104 0.103 0.104 0.104 0.102 0.101 0.103 0.101 0.102 0.100 0.104 0.104 0.100 0.100 0.103 0.102 0.102 0.101 0.105 0.105 0.100 0.103 0.104 0.103 0.104 0.100 0.100 0.105 0.101 0.102 0.104 0.104 0.100 0.101 0.105 0.103 0.105 0.103 0.100 0.102 0.102 0.101 0.103 0.101 0.102 0.103 0.101 0.103 0.102 0.102 0.101 0.103 0.105 0.100 0.103 0.105 0.102 0.105 0.105 0.100 0.105 0.103 0.105 0.102 0.100 0.103 0.102 0.102 0.100 0.104 0.105 0.105 0.101 0.101 0.105 0.102 0.103 0.105 0.102 0.102 0.103 0.101 0.101 0.103 0.101 0.100 0.103 0.100 0.105 0.102 0.103 octave:3>
octave:3> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
0.100 0.105 0.101 0.104 0.104 0.104 0.100 0.105 0.102 0.100 0.102 0.104 0.104 0.104 0.102 0.102 0.105 0.100 0.100 0.100 0.104 0.105 0.103 0.102 0.100 0.101 0.105 0.103 0.101 0.105 0.105 0.103 0.105 0.103 0.102 0.101 0.102 0.102 0.102 0.103 0.104 0.102 0.100 0.105 0.103 0.103 0.102 0.104 0.101 0.102 0.103 0.104 0.102 0.100 0.100 0.105 0.103 0.105 0.103 0.101 0.103 0.100 0.101 0.103 0.102 0.104 0.103 0.101 0.101 0.101 0.100 0.101 0.103 0.104 0.105 0.101 0.104 0.100 0.105 0.102 0.102 0.100 0.100 0.100 0.103 0.100 0.103 0.101 0.102 0.105 0.104 0.102 0.100 0.100 0.105 0.103 0.101 0.102 0.103 0.102 octave:4>
octave:4> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
9.886 10.100 1.995 9.004 9.492 2.193 0.100 9.885 0.268 10.100 10.100 10.100 10.100 10.100 7.839 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 4.101 0.100 0.100 0.100 10.100 10.100 10.100 10.100 3.927 10.100 10.100 5.528 10.100 0.446 4.933 0.100 1.471 3.391 0.464 0.158 0.100 5.041 10.100 10.100 10.100 10.100 0.630 10.100 5.920 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 3.500 10.100 10.100 10.100 10.100 10.100 10.100 0.356 3.030 0.120 0.104 0.103 0.102 0.102 0.223 0.549 0.412 7.863 10.100 0.875 1.553 0.100 10.100 10.100 10.100 4.155 1.534 10.100 5.539 10.100 octave:5>

> If it is a process scheduling issue, what happens if you give it an increased priority using the nice shell command?


I tried the `renice -n -20 -p PID` approach, and it had no apparent effect. Pauses continued to take around 10 seconds for many of the calls:

octave:6> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
1.545 0.100 0.800 10.100 5.822 5.668 1.427 1.456 0.848 0.252 4.243 0.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 4.016 10.100

Similar behavior with `--no-line-editing`: after about 150 calls to pause, it suddenly slows way down:

$ octave-default -q -f --no-line-editing
octave:1> ^[[A^[[A^C

octave:1> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
0.104 0.105 0.100 0.100 0.102 0.103 0.101 0.101 0.103 0.100 0.100 0.101 0.100 0.105 0.103 0.103 0.103 0.102 0.101 0.102 0.103 0.102 0.103 0.101 0.102 0.101 0.102 0.102 0.102 0.101 0.100 0.104 0.100 0.103 0.102 0.104 0.103 0.104 0.101 0.103 0.102 0.102 0.101 0.100 0.105 0.102 0.103 0.100 0.100 0.103 0.101 0.103 0.104 0.100 0.101 0.103 0.100 0.105 0.102 0.101 0.105 0.103 0.102 0.101 0.102 0.100 0.103 0.105 0.100 0.100 0.100 0.101 0.103 0.101 0.102 0.102 0.102 0.105 0.100 0.103 0.105 0.100 0.103 0.101 0.103 0.100 0.105 0.102 0.105 0.104 0.101 0.103 0.102 0.103 0.101 0.101 0.103 0.103 0.104 0.105 octave:2> for i = 1:100; t0 = tic; pause(0.1); te = toc(t0); fprintf('%.3f ', te); endfor
0.104 0.101 0.103 0.102 0.102 0.104 0.105 0.102 0.101 0.105 0.104 0.102 0.102 0.105 0.103 0.105 0.102 0.102 0.104 0.102 0.100 0.101 0.100 0.102 0.104 0.100 0.103 0.103 0.102 0.102 0.101 0.103 0.105 0.103 0.103 0.104 0.100 0.105 0.105 0.102 0.104 0.103 0.103 0.102 0.101 0.103 0.105 0.102 0.100 0.100 0.103 0.102 8.904 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 10.100 7.395 7.880 9.794 3.160 2.323 0.214 0.101 0.101 0.101 0.105 0.101 0.102 0.102 0.105 0.100 0.100 0.103 0.135 0.623 0.253 10.100 10.100 10.100 8.501 0.171 10.100 6.027 10.100 10.100 10.100 10.100 0.847 0.100 0.334 0.100 0.111 0.109 octave:3>

Andrew Janke <apjanke>
Tue 21 May 2019 04:21:33 PM UTC, comment #36:

The pause logic was re-done in this changeset

changeset: 27094:f16471efcdf4
user: Pantxo Diribarne <pantxo.diribarne@gmail.com>
date: Thu May 16 23:08:54 2019 +0200
summary: Fix Fpause timing accuracy when graphics events are processed (bug #56336)

It might be worth compiling a version of Octave after revision 27094 and seeing whether there is any improvement.

Rik <rik5>
Project Administrator
Wed 20 Mar 2019 05:39:48 PM UTC, comment #35:

I don't see much in the dtruss log that helps me pinpoint anything.

If it is a process scheduling issue, what happens if you give it an increased priority using the nice shell command?

Steps to try

1) start Octave
2) Find PID of Octave in another terminal
3) renice -n -20 -p PID
4) now run delay.oct file in Octave

Also, another guess at something to try, maybe there is an interaction with the Readline event hook.

Try starting octave like so

octave -f -q --no-line-editing

and then running the delay.oct file.

Rik <rik5>
Project Administrator
Wed 20 Mar 2019 01:20:18 AM UTC, comment #34:

May be this is useful:

https://stackoverflow.com/questions/3007868/how-can-i-get-dtrace-to-run-the-traced-command-with-non-root-priviledges

Dmitri.
--

Dmitri A. Sergatskov <dasergatskov>
Wed 20 Mar 2019 12:49:37 AM UTC, comment #33:

No, you're probably right to use the first form. I forgot that the "octave" binary does a fork and exec so the original program does exit immediately.

Rik <rik5>
Project Administrator
Wed 20 Mar 2019 12:18:18 AM UTC, comment #32:

> strace octave -f -q tst_delay.m > strace.log


That didn't work. I tried:

sudo dtruss /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave -f -q tst_delay.m &> dtruss-tst_delay.log

But it just exited right away.

I'm probably just not using dtruss right; I know its interface is not identical to strace.

Andrew Janke <apjanke>
Wed 20 Mar 2019 12:08:13 AM UTC, comment #31:

Oho, here we go:

  • Start octave in one terminal. Use getpid to get its pid
  • In another terminal, `sudo dtruss -p <octave_pid> &> dtruss.log`

Here's what I ran in octave:

$ /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave -q -f
octave:1> ls
delay.cpp delay.oct dtruss.log
octave:2> getpid
ans = 125
octave:3> delay
Using nanosleep (&delay_timespec, &rem);
Step 0: elapsed = 6.815449
Step 1: elapsed = 2.316145
.
Step 3: elapsed = 0.546556
.
Step 5: elapsed = 6.845411
.
Step 7: elapsed = 1.023927
Step 8: elapsed = 1.137397
.
Step 10: elapsed = 1.886247
.
Step 12: elapsed = 10.200042
Step 13: elapsed = 10.200091
Step 14: elapsed = 10.200055
Step 15: elapsed = 0.625088
.
Step 17: elapsed = 7.162752

Aborting because it's taking too darn long.


octave:4> exit

And here's the resulting dtruss.log: file #46590

Andrew Janke <apjanke>
Wed 20 Mar 2019 12:07:07 AM UTC, comment #30:

Oho, here we go:

  • Start octave in one terminal. Use getpid to get its pid
  • In another terminal, `sudo dtruss -p <octave_pid> &> dtruss.log`

Here's what I ran in octave:

$ /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave -q -f
octave:1> ls
delay.cpp delay.oct dtruss.log
octave:2> getpid
ans = 125
octave:3> delay
Using nanosleep (&delay_timespec, &rem);
Step 0: elapsed = 6.815449
Step 1: elapsed = 2.316145
.
Step 3: elapsed = 0.546556
.
Step 5: elapsed = 6.845411
.
Step 7: elapsed = 1.023927
Step 8: elapsed = 1.137397
.
Step 10: elapsed = 1.886247
.
Step 12: elapsed = 10.200042
Step 13: elapsed = 10.200091
Step 14: elapsed = 10.200055
Step 15: elapsed = 0.625088
.
Step 17: elapsed = 7.162752

Aborting because it's taking too darn long.

octave:4>

And h

(file #46590)

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:58:08 PM UTC, comment #29:

Another choice is to put the original Octave code in to an m-file (I'm attaching tst_delay.m to this bug report) and then run

strace octave -f -q tst_delay.m > strace.log

(file #46589)

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 11:54:17 PM UTC, comment #28:

if it is anything like "strace" you should be able to run interactive re-directing stderr:

strace octave -q -f 2> strace.log
octave:1>

(etc...)

Dmitri.

Dmitri A. Sergatskov <dasergatskov>
Tue 19 Mar 2019 11:49:16 PM UTC, comment #27:

> This is really bizarre. Is the OS scheduler doing something odd? Maybe it notices that the process is sleeping a lot and it schedules it for infrequent re-activation?


Your guess is as good as mine. That's what it kinda sounds like. I'm no expert in this area, and I don't know how to examine the behavior of the scheduler. My naive Googling for it isn't helping yet.

I'm reading through this book off and on: https://www.amazon.com/Mac-OS-iOS-Internals-Apples/dp/1118057651. Maybe it will help.

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:46:36 PM UTC, comment #26:

> Can you run it through MacOS "strace" equivalent ("dtruss"?) and see if that gives some clues?


I can't get this working. When run under "dtruss", octave just seems to quit right away instead of running code.

Command I tried:

sudo dtruss /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave --eval 'delay' &> dtruss-octave-delay.log

Here's my log file: file #46588

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:23:15 PM UTC, comment #25:

This is really bizarre. Is the OS scheduler doing something odd? Maybe it notices that the process is sleeping a lot and it schedules it for infrequent re-activation?

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 10:52:22 PM UTC, comment #24:

Can you run it through MacOS "strace" equivalent ("dtruss"?) and see if that gives some clues?

Dmitri.
--

Dmitri A. Sergatskov <dasergatskov>
Tue 19 Mar 2019 10:15:20 PM UTC, comment #23:

Thanks!

Minor bug in delay.cpp:

else if (option = 2)

That should be "option == 2", otherwise the else case (for direct call of nanosleep) will never get hit.

I've added it to my test repo and modified the output so it only reports too-long pauses, to make it easier to copy-and-paste output here. A simple "." indicates a sleep that took less than 2x as long as requested. https://github.com/apjanke/test-nanosleep-for-octave/blob/1fa1269bcdad7f4d88cdee1b0037b34f6be526ca/src-octfiles/delay.cpp

I've compiled it and run it under Octave 5.1.0. (Octave default is not building for me right now.)

Results:

octave:1> delay
Using nanosleep (&delay_timespec, &rem);
....................................................................................................
octave:2> delay(1)
Using octave::sleep (0.200000, true)
Step 0: elapsed = 16.175480
Step 1: elapsed = 20.200037
Step 2: elapsed = 20.200055
Step 3: elapsed = 13.168963
[...]
octave:1> delay(2)
Using octave::sleep (0.200000, false)
....................................................................................................
octave:2>

Or:

octave:1> delay(1)
Using octave::sleep (0.200000, true)
....................................................................................................
octave:2> delay(1)
Using octave::sleep (0.200000, true)
..................................
Step 34: elapsed = 9.620640
Step 35: elapsed = 9.745313
Step 36: elapsed = 1.790912
Step 37: elapsed = 10.799203
Step 38: elapsed = 2.362160
Step 39: elapsed = 2.889009
Step 40: elapsed = 3.791923
Step 41: elapsed = 1.356964
Step 42: elapsed = 18.020698

Aborting because it's taking too darn long.

octave:3>

For a bit, I thought that the `octave::sleep (x, false)` case didn't cause problems, but then I ran this:

octave:1> delay(2)
Using octave::sleep (0.200000, false)
....................................................................................................
octave:2> delay(2)
Using octave::sleep (0.200000, false)
......................................
Step 38: elapsed = 9.160260
Step 39: elapsed = 11.657525
Step 40: elapsed = 20.216943
Step 41: elapsed = 20.581857

Aborting because it's taking too darn long.

octave:3> delay(2)
Using octave::sleep (0.200000, false)
Step 0: elapsed = 14.097041
Step 1: elapsed = 12.041813
Step 2: elapsed = 8.248526
Step 3: elapsed = 19.842456
Step 4: elapsed = 17.350757

Aborting because it's taking too darn long.

octave:4>

The direct nanosleep call causes problems, too!

octave:1> delay
Using nanosleep (&delay_timespec, &rem);
....................................................................................................
octave:2> delay
Using nanosleep (&delay_timespec, &rem);
............................
Step 28: elapsed = 8.850037
Step 29: elapsed = 10.200040
Step 30: elapsed = 10.200059
Step 31: elapsed = 10.200043
Step 32: elapsed = 10.200044
Step 33: elapsed = 10.200041

Aborting because it's taking too darn long.

octave:3> delay
Using nanosleep (&delay_timespec, &rem);
Step 0: elapsed = 8.751405
Step 1: elapsed = 1.168990
Step 2: elapsed = 10.200013
.
Step 4: elapsed = 10.200064
Step 5: elapsed = 10.200065
Step 6: elapsed = 10.200068
Step 7: elapsed = 10.200046

Aborting because it's taking too darn long.

octave:4>

WTF?

So, to me, that doesn't sound like it's a problem in the pause() logic, but something else.

Andrew Janke <apjanke>
Tue 19 Mar 2019 09:06:14 PM UTC, comment #22:

@Andrew: Can you try the attached delay.cpp? Compile it as a .octfile with

mkoctfile delay.cpp

Then try running it with options 0, 1, and 2. The documentation is

USAGE: delay (OPT)
OPT = 0 : nanosleep
OPT = 1 : octave::sleep (0.2, true)
OPT = 2 : octave::sleep (0.2, false)

This might help distinguish which code path is failing.

(file #46584)

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 05:51:37 PM UTC, comment #21:

> Is it possible that the delay is accurate when run in Octave, but the reporting is incorrect? In other words, is there something wrong with tic/toc?


I don't think so. I sat there watching it, and it definitely took 20-30 seconds sometimes.

The only reason I noticed this in the first place is that pause started taking so long that I thought my code was hung.

Andrew Janke <apjanke>
Tue 19 Mar 2019 05:47:14 PM UTC, comment #20:

Is it possible that the delay is accurate when run in Octave, but the reporting is incorrect? In other words, is there something wrong with tic/toc?

I put the following code in a file tst_delay.m

for i = 1:100
pause(0.2);
disp (i);
endfor

Then I ran

time run-octave -f tst_delay.m
0.385u 0.123s 0:20.58 2.4% 0+0k 20960+144io 116pf+0w

The third column is wall time which is about 20 seconds and is what I would expect for 100, 0.2 second delays.

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 04:53:27 PM UTC, comment #19:

I got the test project building on my system too, with Mike's help.

When I run the test on the same machine that shows the weird long pause behavior in Octave, its pauses go for 200 ms each time, with only 1 or two ms variation. It doesn't reproduce the weird pause behavior.

$ src/my_nanosleep_test master ◼
Step 0: elapsed = 0.204960
Step 1: elapsed = 0.200963
Step 2: elapsed = 0.200300
Step 3: elapsed = 0.201304
[... and then 100 more lines that look just like that...]

Andrew Janke <apjanke>
Mon 18 Mar 2019 08:57:23 PM UTC, comment #18:

Your test project works for me, and in fact on my system the gnulib replacement is also used, I get "mishandles large arguments", so the shim function "rpl_nanosleep" is used.

The test program runs to 99 on my system with 0.2 seconds each time, and I also can't reproduce this in Octave.

Mike Miller <mtmiller>
Project Administrator
Mon 18 Mar 2019 07:51:24 PM UTC, comment #17:

Anybody know enough about gnulib and autotools to help me get a minimal test program working?

https://github.com/apjanke/test-nanosleep-for-octave

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:21:25 PM UTC, comment #16:

> … that uses the right gnulib nanosleep wrapper and see how it behaves.


Darn it. I'll need to get set up for gnulib use. Stand by...

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:20:52 PM UTC, comment #15:

Test program:

#include <time.h>
#include <stdio.h>
#include <ctime>
#include <chrono>

extern "C"
int main (int argc, char *argv[]) {
using namespace std::chrono;

int n = 100;
int delay = 200;

time_t tv_sec = 0;
long tv_nsec = delay * 1000000;
struct timespec delay_timespec;
delay_timespec.tv_sec = tv_sec;
delay_timespec.tv_nsec = tv_nsec;

struct timespec rem;

for (int i = 0; i < n; i++) {
high_resolution_clock::time_point t0 = high_resolution_clock::now();
nanosleep (&delay_timespec, &rem);
high_resolution_clock::time_point t1 = high_resolution_clock::now();
duration<double> time_span = duration_cast<duration<double> >(t1 - t0);

printf ("Step %4d: elapsed = %f\n", i, time_span.count());
}
}

Results:

$ ./a.out
Step 0: elapsed = 0.202791
Step 1: elapsed = 0.201132
Step 2: elapsed = 0.200450
Step 3: elapsed = 0.200035
Step 4: elapsed = 0.201446
Step 5: elapsed = 0.200258
Step 6: elapsed = 0.200578
Step 7: elapsed = 0.200934
[...]

It's within a few milliseconds of 200 ms each time I run it.

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:17:09 PM UTC, comment #14:

> write a stand-alone C++ program that calls nanosleep and see if it also behaves incorrectly.


… that uses the right gnulib nanosleep wrapper and see how it behaves.

On macOS, Andrew should be using the nanosleep wrapper in libgnu/nanosleep.c inside the '#if HAVE_BUG_BIG_NANOSLEEP' conditional.

Mike Miller <mtmiller>
Project Administrator
Mon 18 Mar 2019 05:12:42 PM UTC, comment #13:

@Andrew: Oops, my comment #12 got interspersed with jwe's comments. We are both looking for the same thing. Is this a problem with Octave or a problem with the system library?

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 05:08:51 PM UTC, comment #12:

To test, you could write a stand-alone C++ program that calls nanosleep and see if it also behaves incorrectly.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 05:04:56 PM UTC, comment #11:

When I first made pause interruptible (http://hg.savannah.gnu.org/hgweb/octave/rev/6b3c78f84d3b in response to bug #52876) it was not handling graphics events during the pause. Now that it does process graphics events while paused, I agree with Rik that we need to fix it to account for any time spent processing those events. Also, what should happen if one of those graphics events calls pause?

Regardless, it is surprising to me that any graphics events would cause this much of a delay. I see up to 500ms extra delay, but usually around 10ms.

To verify that it is graphics event processing that is causing the trouble, what happens if you remove the calls to gh_manager::process_events in the void sleep (double seconds, bool do_graphics_events) function in libinterp/corefcn/utils.cc?

Hmm, what Andrew wrote in comment #4 indicates that maybe it isn't the graphics events causing the trouble?

Could you also insert some statements to trace the calls to the nanosleep wrapper to see whether it is a general delay (all calls take about the same amount of time, just longer than expected) or if most calls take approximately the requested delay and some MUCH longer?

John W. Eaton <jwe>
Project Administrator
Mon 18 Mar 2019 04:47:51 PM UTC, comment #10:

> Thanks. I think re-coding is required then.


The one thing that makes me question this is that the delay also happens when calling java.lang.Thread.sleep(), which is unrelated to Octave's pause() code.

octave:1> for i = 1:100; t0 = tic; javaMethod("sleep", "java.lang.Thread", 200); te = toc (t0); fprintf ("%.3f ", te); endfor
2.149 0.201 4.001 8.345 7.763 0.204 0.200 3.331 1.850 10.200 4.044 0.226 0.204 0.201 0.202 0.202 0.203 0.209 10.200 1.948 1.312 0.203 0.571 0.250 5.678 10.202 2.923 10.201 10.207 10.200 10.200 10.206 4.998 1.045 0.200 0.200 10.200 0.300 9.712 6.791 4.549 10.200 10.200 10.200 10.200 10.200 10.200 0.807 1.683 10.200 10.200 3.955 0.251 10.200 10.200 2.706 0.200 1.221 0.201 0.200 10.200 10.200 0.847 10.201 5.014 0.207 7.375 5.421 3.119 1.234 10.200 10.200 10.200 10.200 8.764 0.201 6.226 1.285 10.201 2.811 10.200 2.842 0.200 3.964 0.200 0.200 0.201 0.312 0.217 0.200 0.200 0.200 0.462 0.879 6.400 0.200 10.171 0.200

Andrew Janke <apjanke>
Mon 18 Mar 2019 04:35:00 PM UTC, comment #9:

Thanks. I think re-coding is required then.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 04:17:28 PM UTC, comment #8:

> Also, when testing, are you starting octave with -f so there are no user configuration settings that might be affecting this?


No. But I tried it just now, and it's showing the same behavior.

Andrew Janke <apjanke>
Mon 18 Mar 2019 04:10:34 PM UTC, comment #7:

Also, when testing, are you starting octave with -f so there are no user configuration settings that might be affecting this?

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 04:09:33 PM UTC, comment #6:

> As a further test, could you try changing the pause amount to an integral number of seconds (i.e., try 1) and see what happens?


octave:1> for i = 1:100; t0 = tic; pause (1); te = toc(t0); fprintf ("%.3f ", te); endfor
62.647 62.345 55.108 1.885 22.466 6.629 38.655 29.702 13.820 4.671 44.841 82.826 14.903 41.600 79.183 31.170

Ouch.

Andrew Janke <apjanke>
Mon 18 Mar 2019 03:50:57 PM UTC, comment #5:

So, I guess we can confirm this as being real, but only for Mac platforms.

The Octave code for the sleep() call is in libinterp/corefcn/utils.cc (sleep).

As a further test, could you try changing the pause amount to an integral number of seconds (i.e., try 1) and see what happens?

Looking at the code, it is much more complicated than one would have first thought. I imagined that Octave was just calling the library function sleep or nanosleep with the appropriate delay.

Instead, in order to have the interpreter respond interactively to signals (such as Ctrl+C), the total delay is split in to 100 millisecond segments and after every segment Octave checks whether there has been a signal event. It also runs any GUI or plot events if the do_graphics_events input to the function is true. That could be where the variable delay is getting inserted.

I think, irregardless of the fact that this seems to work on Linux, that this is not the right strategy. I think we should use something similar to what Pantxo coded for movie.m which I will quote below.

## Initialize the timer
t = tau = 1/fps;
timerid = tic ();

for ii = idx
cdata = mov(ii).cdata;
if (isempty (cdata))
error ("movie: empty image data at frame %d", ii);
endif
set (him, "cdata", cdata);

if (! isempty (mov(ii).colormap))
set (hax, "colormap", mov(ii).colormap)
endif

pause (t - toc (timerid));
t += tau;
endfor

The point is that any work done in the loop is accounted for and reduces the length of the pause. If the time to pause is negative--because so much work was done in the loop--then pause is skipped which gets the delay engine back on track.

This would need to be re-coded in C++, but it isn't that hard.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 02:20:17 PM UTC, comment #4:

I can't reproduce this on Linux or Windows, even in VMs on the original machine where this first appeared.

I can reproduce it on other Mac machines. The first one where I saw it was angharad, a 5K iMac running Mojave. Here's behavior on toast, my 13" MacBook Pro, under 5.1.0, while the machine is lightly loaded.

octave:1> for i = 1:200; t0 = tic; pause (0.2); fprintf ("%.3f ", toc(t0)); endfor
9.602 0.358 0.722 0.201 0.629 0.201 0.209 0.210 0.204 0.204 20.079 0.357 0.526 0.201 4.780 4.353 5.048 0.260 0.280 1.026 1.370 2.339 2.005 0.336 6.454 2.532 3.683 2.337 3.339 5.218 1.194 1.346 3.822 1.101 5.375 0.916 3.054 1.139 6.354 6.535 1.158 1.137 2.424 1.440 5.022 5.926 2.021 9.747 2.177 11.538 6.867 4.241 15.702 17.544 4.638 2.037 4.483 0.443 0.202 0.202 0.203 0.202 0.594 0.200 2.834 8.706 6.874 1.077 10.200 12.957 11.588 3.485 3.597 12.418 1.380 10.200 20.971 1.552 1.693 5.222 12.353 10.511 18.575 14.750 14.891 ^C
octave:1> for i = 1:200; t0 = tic; javaMethod("sleep", "java.lang.Thread", 200); fprintf ("%.3f ", toc(t0)); endfor
10.556 3.444 1.077 0.201 0.234 3.931 0.943 5.128 4.294 0.656 3.448 6.198 3.912 1.321 4.741 0.204 10.201 4.284 1.626 10.201 8.528 0.201 10.201 0.815 0.201 0.209 0.200 0.200 0.205 0.328 0.204 0.206 0.204 0.206 0.202 10.201 10.201 10.201 10.201 10.201 3.039 3.000 0.201 0.201 0.201 0.523 2.135 0.335 0.200 0.201 0.359 0.201 0.771 0.200 0.200 1.785 0.495 1.104 0.316 0.832 0.201 0.934 0.909 0.402 1.324 0.289 1.939 2.635 0.982 0.201 0.958 1.583 1.020 0.201 2.138 0.201 0.947 1.392 1.185 0.489 0.825 0.201 1.450 1.117 10.201 8.015

Happens for me in 4.4.1, 5.1.0, and default. Again, on this machine, it only happens in the CLI, not the GUI of the same Octave, even if run at the same time as a CLI octave process is exhibiting this behavior.

One thing I noticed is that it takes a while for Octave to respond to Ctrl-C inputs when this is happening. So it seems like one of the individual sleep intervals or graphics-handling steps in octave::sleep() is taking a while. And the fact that java.lang.Thread.sleep is also taking a long time suggests that it's not octave::sleep's code that's doing anything weird; it's something about the overall process or machine state that's causing regular sleeps to take a long time.

Andrew Janke <apjanke>
Mon 18 Mar 2019 12:57:43 PM UTC, comment #3:

This also works for me on linux and Windows (Octave 4.4.0).

Pantxo Diribarne <pantxo>
Project Member
Mon 18 Mar 2019 04:37:42 AM UTC, comment #2:

This works for me, but I'm running on Linux.

It would be good to see if anyone else can replicate this.

Rik <rik5>
Project Administrator
Sun 17 Mar 2019 02:50:26 PM UTC, comment #1:

Seems to affect java.lang.Thread.sleep, too.

octave:1> for i = 1:100; t0 = tic; javaMethod('sleep', 'java.lang.Thread', 200); te = toc(t0); fprintf('%.3f ', te); endfor
10.200 10.200 10.200 10.200 8.327 4.591 0.200 10.200 0.200 0.351 0.204 0.202 0.202 10.200 0.561 8.691 0.510 0.253 0.200 10.200 10.200 7.787

My system isn't heavily loaded, so this is kind of surprising.

Processes: 534 total, 2 running, 2 stuck, 530 sleeping, 3390 threads 10:49:39
Load Avg: 2.36, 2.72, 2.74 CPU usage: 3.10% user, 1.91% sys, 94.98% idle
SharedLibs: 417M resident, 56M data, 117M linkedit.
MemRegions: 175577 total, 6879M resident, 162M private, 3773M shared.
PhysMem: 29G used (3496M wired), 3379M unused.
VM: 4171G vsize, 1298M framework vsize, 127888(64) swapins, 159496(0) swapouts.
Networks: packets: 130791589/54G in, 210108728/241G out. Disks: 106966529/1578G read, 32295703/513G written.

Andrew Janke <apjanke>
Sun 17 Mar 2019 02:40:10 PM UTC, original submission:

If I call pause() several times in a row, with only a little work done in between calls, eventually pause() starts taking much longer than the specified time, causing hangs.

```
octave:1> for i = 1:100; t0 = tic; pause(0.2); te = toc(t0); fprintf("%.3f\n", te); endfor
0.201
0.205
0.201
0.201
0.202
0.201
0.205
0.205
0.204
0.205
0.201
0.200
0.201
0.201
0.201
0.204
0.204
0.204
0.203
0.201
0.201
0.204
0.200
0.209
0.204
0.204
0.204
0.202
0.201
0.202
0.202
0.200
0.201
0.202
0.201
0.201
3.062
5.919
1.926
1.296
5.152
1.621
20.200
8.701
2.147
5.800
2.533
2.446
0.587
3.142
4.628
0.213
8.256
0.253
1.068
10.200
14.527
20.200
```

Only seems to affect CLI Octave; doesn't happen in the GUI Octave.

Affects 4.4.1, 5.1.0, and default.

Andrew Janke <apjanke>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #46590:  dtruss.log.gz added by apjanke (3KiB - application/x-gzip)
file #46589:  tst_delay.m added by rik5 (88B - text/x-matlab)
file #46588:  dtruss-octave-delay_not-working-01.log added by apjanke (3KiB - application/octet-stream)
file #46584:  delay.cpp added by rik5 (1KiB - text/x-c++src)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by dasergatskov (Posted a comment)
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by pantxo (Posted a comment)
  • -email is unavailable- added by rik5 (Posted a comment)
  • -email is unavailable- added by apjanke (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can add your encouragement to it.
    This task has 0 encouragements so far.

    Only project members can vote.

     

     

     

    Follow 10 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-05-22 rik5 Item GroupIncorrect Result => Feature Request
        Release5.1.0 => dev
        Summarypause() takes too long if you call it a bunch => [Mac] Disable App Nap, either selectively or for all of Octave
    2019-05-22 rik5 CategoryOctave Function => None
    2019-03-20 apjanke Attached File- => Added dtruss.log.gz, #46590
    2019-03-19 rik5 Attached File- => Added tst_delay.m, #46589
    2019-03-19 apjanke Attached File- => Added dtruss-octave-delay_not-working-01.log, #46588
    2019-03-19 rik5 Attached File- => Added delay.cpp, #46584
    2019-03-18 rik5 StatusWorks For Me => Confirmed
    2019-03-18 rik5 StatusNone => Works For Me

    Back to the top


    Powered by Savane 3.4