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

 
 

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

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

Add a New Comment Rich Markup
   

Jump to the original submission

Mon 04 Nov 2019 03:46:05 AM UTC, comment #64: 

I pushed your fix for the indentation.

Rik <rik5>
Group administrator
Mon 04 Nov 2019 02:40:36 AM UTC, comment #63: 

Here's a patch to fix the indentation: https://savannah.gnu.org/bugs/download.php?file_id=47801

Builds and tests okay for me locally.

Andrew Janke <apjanke>
Sun 03 Nov 2019 06:34:03 PM UTC, comment #62: 

I saw the indentation issue as well, but I was just tired at that point.  I think it would probably be preferable to remove the indent, but I'm also kay leaving it.

In any case, I'm going to mark this as fixed and close the report.

Rik <rik5>
Group administrator
Sun 03 Nov 2019 05:21:24 PM UTC, comment #61: 

Looks good to me. Thanks for the cleanup. I'll get better at this some day, I promise.

I think that nullptr change is fine.

Tests okay on my macOS 10.14.6 machine: I can build from default, it runs, and pause() doesn't seem to slow down now, in either terminal or GUI.

You know what, now that it's a static function, and not inside the "namespace octave { ... }", should it be indented inside the "#if defined (Q_OS_MAC)"? I'm thinking probably not.

It's on my TODO list to make a macOS 10.15 VM and start testing stuff there too, but that will take a little time.

Andrew Janke <apjanke>
Sun 03 Nov 2019 04:44:53 PM UTC, comment #60: 

I did a bit more cleanup--wrapping long lines to 80 columns if possible, replacing C comparison to NULL with C++ comparison to nullptr, dropping FIXME note about static function--and checked things in here https://hg.savannah.gnu.org/hgweb/octave/rev/39fac14ab25a.

I'm marking as Ready for Test since it's just possible that the change to compare to nullptr would make a difference, even though it is the "right" thing to do.

Rik <rik5>
Group administrator
Sun 03 Nov 2019 04:07:32 PM UTC, comment #59: 

file $47785 applies, compiles, and runs for me.

Ben Abbott <bpabbott>
Group Member
Sun 03 Nov 2019 03:17:29 PM UTC, comment #58: 

BTW, now that I can get it to build and test, it seems to work: pause() doesn't slow down in my testing.

Andrew Janke <apjanke>
Sun 03 Nov 2019 03:15:54 PM UTC, comment #57: 

I think the API signature change is a red herring here. The objc_msgSend signature change is in the upcoming macOS 10.15, not the current 10.14. (References: http://codeworkshop.net/objc-diff/sdkdiffs/macos/10.15/Objective-C.html, https://www.mikeash.com/pyblog/objc_msgsends-new-prototype.html.)

I think the problem was just that my code was missing a cast in the first place.

Attached a patch which gets the code compiling by adding a cast, and enables it: https://savannah.gnu.org/bugs/download.php?file_id=47785. Also finishes converting it to a static function.

Andrew Janke <apjanke>
Sat 02 Nov 2019 03:15:30 PM UTC, comment #56: 

@Rik

Any thoughts on a fix for new versions of macOS? How to work around the signature change? I haven't been keeping up with Apple's changes, so I'm quite naive about this.

Ben Abbott <bpabbott>
Group Member
Sat 02 Nov 2019 03:09:38 PM UTC, comment #55: 

I pushed a different change here (https://hg.savannah.gnu.org/hgweb/octave/rev/1c13a0f36160).  The problem with reverting is that the code is likely to be forgotten.  Instead, I used #if 0 / #endif to disable the blocks of code for the App Nap patch.  I also added a note with the bug number above each such block.  Hopefully the visual reminder will be sufficient that someone returns to this soon.

The problem is not with the original code, but with Apple, who has recently changed the function signature in their libraries for objc_msgSend().  To resolve this a configure test needs to be written, probably AC_COMPILE_IFELSE, which attempts to compile with the older function signature.  THat can set set a configuration variable in config.h which can then be used to condition the function  call within disable_app_nap.

Rik <rik5>
Group administrator
Sat 02 Nov 2019 04:06:22 AM UTC, comment #54: 

Thanks.

I agree with the analysis that we're "close" to getting this working and it probably would be an "easy" change. But right now I have zero hours to give to this for the next few weeks, due to day job commitments. And the current state is that the default build is broken on the latest macOS, which I think is bad.

Please merge the patch to revert, and I'll come back with a better-tested changeset later.

Andrew Janke <apjanke>
Sat 02 Nov 2019 01:55:43 AM UTC, comment #53: 

Attached a patch to revert this change.

(file #47775)

Ben Abbott <bpabbott>
Group Member
Tue 29 Oct 2019 04:16:55 AM UTC, comment #52: 

Build failure, I'm afraid.


/Applications/Xcode-10.3.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.14.sdk/usr/include/objc/message.h:85:1: note: candidate function not viable: no known conversion from 'Class _Nullable' (aka 'objc_class *') to 'id _Nullable' (aka 'objc_object *') for 1st argument
objc_msgSend(id _Nullable self, SEL _Nonnull op, ...)
^
libgui/src/octave-qobject.cc:222:5: error: use of undeclared identifier 'osx_latencycritical_activity'
    osx_latencycritical_activity = objc_msgSend (process_info,
    ^


Please revert, and let me get a working build using this change set as a patch before committing again.

> Also, when you get around to testing, could you check whether the function disable_app_nap needs to be  member function (even though private) of base_qobject?  It seems like it would be simpler to have the function be a static file local function in base_qobject.cc that is never seen outside the file.


Oh, I think static would work fine. It's just my habit to make things member functions, since I'm a Java-head. I'll do that instead.

Andrew Janke <apjanke>
Mon 28 Oct 2019 12:02:57 AM UTC, comment #51: 

@Andrew: I took your rough draft patch and added commit messages, you as the author, and some FIXME notes before checking it in here https://hg.savannah.gnu.org/hgweb/octave/rev/d0fe6e344c41.

I've marked the bug as Ready for Test since I can't confirm that the patch works or not.  Also, when you get around to testing, could you check whether the function disable_app_nap needs to be  member function (even though private) of base_qobject?  It seems like it would be simpler to have the function be a static file local function in base_qobject.cc that is never seen outside the file.

Rik <rik5>
Group administrator
Sat 12 Oct 2019 10:16:42 AM UTC, comment #50: 

Here's a first draft at disabling App Nap.

I'm currently having unrelated problems getting default to build, so I haven't been able to actually test it yet.

https://savannah.gnu.org/bugs/download.php?file_id=47658

Andrew Janke <apjanke>
Sat 12 Oct 2019 09:33:31 AM UTC, comment #49: 

I'll try!

This one's going to be a little trickier: we need to not only #ifdef it to be Mac-only, but also detect whether we're on a macOS version that has App Nap. Or maybe not: what is the minimum version of macOS that Octave 5.x and 6.x require? Maybe we could make it unconditional.

Andrew Janke <apjanke>
Fri 11 Oct 2019 09:21:44 PM UTC, comment #48: 

@Andrew: Since we just wrapped up one Mac-specific bug, do you have a patch for this one too?

Rik <rik5>
Group administrator
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>
Group 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>
Group 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>
Group Member
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>
Group Member
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>
Group 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>
Group Member
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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group Member
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>
Group Member
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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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 #47801:  fix-app-nap-indentation.patch added by apjanke (5KiB - application/octet-stream - Patch to fix source code indentation from previous fix)
file #47785:  fix-app-nap-disabling_apj_20191103.patch added by apjanke (7KiB - application/octet-stream)
file #47775:  changeset.patch added by bpabbott (4KiB - application/octet-stream)
file #47658:  disable-app-nap_apj-try-01.patch added by apjanke (4KiB - application/octet-stream - first draft, do not merge yet)
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 bpabbott (Updated the item)
  • -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)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only group members can vote.

     

    Follow 20 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-11-04 apjanke Attached File- Added fix-app-nap-indentation.patch, #47801
    2019-11-03 rik5 StatusReady For Test Fixed
        Open/ClosedOpen Closed
    2019-11-03 rik5 StatusIn Progress Ready For Test
    2019-11-03 apjanke Attached File- Added fix-app-nap-disabling_apj_20191103.patch, #47785
    2019-11-02 rik5 StatusReady For Test In Progress
    2019-11-02 bpabbott Attached File- Added changeset.patch, #47775
    2019-10-28 rik5 CategoryNone Interpreter
        StatusConfirmed Ready For Test
    2019-10-12 apjanke Attached File- Added disable-app-nap_apj-try-01.patch, #47658
    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.13-f8d8.
    Corresponding source code