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)

Mon 03 Jun 2019 10:42:13 PM UTC, comment #47: 

No progress; sorry. I'm swamped at the day job and at a conference this week, so am unlikely to get anything done for a couple weeks at this point.

Andrew Janke <apjanke>
Mon 03 Jun 2019 04:14:28 PM UTC, comment #46: 

@Andrew: Any progress on an App Nap patch that disables the behavior once at startup?

Rik <rik5>
Project Administrator
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.5