App unresponsive after it has been in the background for some time

[ryandesign]

Describe the bug
If I have the emulator running in the background covered with other windows, when I come back to it, it is unresponsive for several minutes, with the spinning rainbow pinwheel cursor, until it eventually becomes responsive again.

To Reproduce
Steps to reproduce the behavior:

1. Start the emulator.
2. Switch to another application, covering the emulator with other windows.
3. Wait an hour.
4. Switch back to the emulator.

Expected behavior
The app should immediately be fully responsive.

Actual behavior
The app is unresponsive for several minutes.

Versions (please complete the following information):

• OS: macOS 12.7.5
• Mariani: 1.5 (2)

Additional context
Here is a sample taken with Activity Monitor when it is unresponsive:

Sample of Mariani.txt

It seems like there's a ton of stuff descended from __NSFireTimer. It makes me wonder if the emulation constantly fires timers, even when in the background, but they are only processed in the foreground or when the window is not covered, so when the window becomes unobscured again it has a huge backlog to work through.

[sh95014]

Did you capture this sample during the "several minutes" of unresponsiveness after you brought the app back to the foreground?

    + 2267 __NSFireTimer  (in Foundation) + 67  [0x7ff8107add41]
    +   2218 common2::CommonFrame::Execute(unsigned int) (in Mariani) (commonframe.cpp:128) (in Mariani) load address 0x10ca40000 + 0x22c84  [0x10ca62c84]
    +   ! 2211 CpuExecute(unsigned int, bool) (in Mariani) + 131 + 348778  [0x10ca9526a]
    +   ! : 1782 Cpu65C02(unsigned int, bool) (in Mariani) + 181 + 517425  [0x10cabe531]
    +   ! : | 1357 VideoUpdateCycles(int) (in Mariani) + 71 + 742268  [0x10caf537c]
    +   ! : | 320 VideoUpdateCycles(int) (in Mariani) + 154 + 742351  [0x10caf53cf]
    +   ! : 95 Cpu65C02(unsigned int, bool) (in Mariani) + 250 + 517494  [0x10cabe576]
    +   ! : | 22 IO_Cxxx(unsigned short, unsigned short, unsigned char, unsigned char, unsigned int) (in Mariani) + 1156 + 842615  [0x10cb0db77]
    +   ! : 56 Cpu65C02(unsigned int, bool) (in Mariani) + 137 + 517381  [0x10cabe505]
    +   ! : | 13 IRQ(unsigned int&, int&, int&, int&, int&) (in Mariani) + 6 + 670874  [0x10cae3c9a]
    +   ! : 39 Cpu65C02(unsigned int, bool) (in Mariani) + 169 + 517413  [0x10cabe525]
    +   ! : 18 Cpu65C02(unsigned int, bool) (in Mariani) + 11365 + 528609  [0x10cac10e1]
    +   ! : | 10 IORead_C00x(unsigned short, unsigned short, unsigned char, unsigned char, unsigned int) (in Mariani) + 0 + 856816  [0x10cb112f0]
    +   ! 5 CpuExecute(unsigned int, bool) (in Mariani) + 182 + 348829  [0x10ca9529d]
    +   ! : 4 MockingboardCardManager::UpdateCycles(unsigned int) (in Mariani) + 38 + 335600  [0x10ca91ef0]
...
    +   39 common2::CommonFrame::Execute(unsigned int) (in Mariani) (commonframe.cpp:0) + 142498  [0x10ca62ca2]
    +   ! 30 SpkrUpdate(unsigned int) (in Mariani) + 213 + 941119  [0x10cb25c3f]

Looks like it's accumulated a lot of work (mostly video updates) while in the background, which I guess shouldn't surprise me too much on a slower machine:

    self.runLoopTimer = [NSTimer timerWithTimeInterval:0 target:self selector:@selector(runLoopTimerFired) userInfo:nil repeats:YES];
    [[NSRunLoop currentRunLoop] addTimer:self.runLoopTimer forMode:NSRunLoopCommonModes];

Would you be willing to try a test build for me? I don't think I can make my machine prove that the fix will work for you, and I'd rather not make a "release" with experimental code...

[sh95014]

@ryandesign Here's a build that doesn't fire the next timer event until the current one is finished processing, which should avoid the case where it floods itself:

Mariani-one-shot-timer.zip

I'd greatly appreciate if you could try it out to see if it resolves this issue. To avoid confusion with "official" releases, you'll see the name "X-Mariani" in the About box.

[ryandesign]

Did you capture this sample during the "several minutes" of unresponsiveness after you brought the app back to the foreground?

Right.

Would you be willing to try a test build for me?

Sure!

Here's a build that doesn't fire the next timer event until the current one is finished processing, which should avoid the case where it floods itself

What I notice with this build is that when I cover the emulator window entirely, it immediately goes to 102% CPU usage, and when I uncover it, CPU usage gradually goes down to normal again.

[sh95014]

What I notice with this build is that when I cover the emulator window entirely, it immediately goes to 102% CPU usage, and when I uncover it, CPU usage gradually goes down to normal again.

...but it no longer hangs for several minutes when you bring the window to the front?

Can you grab a sample when the CPU is pegged to 100% while in the background? The emulator is being run as often as possible:

    self.runLoopTimer = [NSTimer scheduledTimerWithTimeInterval:0 target:self selector:@selector(runLoopTimerFired) userInfo:nil repeats:YES];

but perhaps the costly screen refreshing work was allowing the CPU to be partially idle when foregrounded...

[ryandesign]

...but it no longer hangs for several minutes when you bring the window to the front?

So far that appears to be true but I haven't left the window covered for more than a few minutes yet.

Can you grab a sample when the CPU is pegged to 100% while in the background? The emulator is being run as often as possible:

Sure: Sample of X-Mariani.txt

[sh95014]

Hah, it's spending >80% of that time just adding timers:

+ ! : | + 1478 __NSFireTimer  (in Foundation) + 67  [0x7ff8107add41]
+ ! : | + ! 736 -[EmulatorViewController runLoopTimerFired] (in Mariani) (EmulatorViewController.mm:273) + 277076  [0x1021e0a54]
+ ! : | + ! : 578 CFRunLoopAddTimer  (in CoreFoundation) + 532  [0x7ff80f9a22f3]
+ ! : | + ! : 52 CFRunLoopAddTimer  (in CoreFoundation) + 540  [0x7ff80f9a22fb]
+ ! : | + ! : 43 CFRunLoopAddTimer  (in CoreFoundation) + 396  [0x7ff80f9a226b]
+ ! : | + ! : 24 CFRunLoopAddTimer  (in CoreFoundation) + 501  [0x7ff80f9a22d4]
+ ! : | + ! 493 -[EmulatorViewController runLoopTimerFired] (in Mariani) (EmulatorViewController.mm:272) + 276959  [0x1021e09df]
+ ! : | + ! : 433 +[NSTimer(NSTimer) scheduledTimerWithTimeInterval:target:selector:userInfo:repeats:]  (in Foundation) + 144  [0x7ff81079e521]
+ ! : | + ! : | 345 CFRunLoopAddTimer  (in CoreFoundation) + 639  [0x7ff80f9a235e]
+ ! : | + ! : | 19 CFRunLoopAddTimer  (in CoreFoundation) + 601  [0x7ff80f9a2338]
+ ! : | + ! : 36 +[NSTimer(NSTimer) scheduledTimerWithTimeInterval:target:selector:userInfo:repeats:]  (in Foundation) + 107  [0x7ff81079e4fc]
+ ! : | + ! 131 -[EmulatorViewController runLoopTimerFired] (in Mariani) (EmulatorViewController.mm:272) + 276916  [0x1021e09b4]
+ ! : | + ! : 75 common2::CommonFrame::Execute(unsigned int) (in Mariani) (commonframe.cpp:128) + 116900  [0x1021b98a4]
+ ! : | + ! : 30 common2::CommonFrame::Execute(unsigned int) (in Mariani) (commonframe.cpp:0) + 116930  [0x1021b98c2]
+ ! : | + ! : | 26 SpkrUpdate(unsigned int) (in Mariani) + 213 + 900491  [0x102278d8b]
+ ! : 378 __CFRunLoopDoTimer  (in CoreFoundation) + 1041  [0x7ff80f9f0a8d]

The AppleWin engine seems to be designed to be called as often as possible, and it doesn't automatically go idle if it doesn't have any more code to execute. I may have to consult a bit upstream to deal with this one...

[sh95014]

...but it no longer hangs for several minutes when you bring the window to the front?

So far that appears to be true but I haven't left the window covered for more than a few minutes yet.

Please let me know when you've been able to verify this. I intend to release that fix independently of the 102%-CPU issue, which I suspect is pretty core to the way AppleWin works. (It can optionally emulate a 6502 running as fast as the host CPU can do it, so in that mode the CPU pegging is expected. It's just a waste of energy when emulating a 1 MHz 6502.)

[sh95014]

Please try this build instead. It should tackle both the unresponsiveness-after-backgrounding and the 100%-CPU issues. About box should indicate X-Mariani 1.5 (3).

Thanks for the reports and your help reproducing these! Much appreciated.

Mariani-one-shot-timer-2.zip

[ryandesign]

Please let me know when you've been able to verify this. I intend to release that fix independently of the 102%-CPU issue,

I haven't seen the unresponsiveness when returning to the app, so I think that much is fixed.

But it's not good the way it is. Before, I could easily leave the emulator running in the background indefinitely, for example while writing code in a fullscreen editor. When I returned to the emulator to test my code, it might just take a little while to catch up. Now, even a few seconds in the background will make my computer hot and loud. That's not conducive to productivity so now I have to quit the emulator rather than leave it running.

Please try this build instead. It should tackle both the unresponsiveness-after-backgrounding and the 100%-CPU issues. About box should indicate X-Mariani 1.5 (3).

Thanks! But it's still doing 102% CPU use when the window is covered. Here's a new sample: Sample of X-Mariani 1.5 (3).txt

[sh95014]

It would help if I didn't comment out the code that's supposed to do the work! 🤦‍♂️

        idleTime = 0;// (1.0 / TARGET_FPS) - timeSpent;

With the correct change in place, the sample on my machine looks a lot more reasonable:

App in foreground:

    7003 Thread_5729668: Main Thread   DispatchQueue_<multiple>
...
    +                   ! : 6983 _CFRunLoopRunSpecificWithOptions  (in CoreFoundation) + 532  [0x18cd55e34]
    +                   ! : | 4978 __CFRunLoopRun  (in CoreFoundation) + 1188  [0x18cc9b4f8]
...
    +                   ! : | + !       4975 mach_msg2_trap  (in libsystem_kernel.dylib) + 8  [0x18cbbac34]
...
    +                   ! : | 1302 __CFRunLoopRun  (in CoreFoundation) + 1816  [0x18cc9b76c]
    +                   ! : | + ! :   | + 1246 common2::CommonFrame::ExecuteOneFrame(long long)  (in Mariani) + 72  [0x102bc9540]  commonframe.cpp:81
...
    +                   ! : | 671 __CFRunLoopRun  (in CoreFoundation) + 1944  [0x18cc9b7ec]
    +                   ! : | +   !   :   | 354 -[EmulatorViewController refreshTexture]  (in Mariani) + 92  [0x102bf4524]  EmulatorViewController.mm:700

So about 20% of the CPU driving the emulator, about 10% refreshing the screen, and about 70% idle. When put behind other windows, the ratios become 17%/9%/73%, which could just be sampling error.

X-Mariani 1.5 (4): Mariani-one-shot-timer-3.zip

[sh95014]

@ryandesign Happy New Year! Here's a better one that more closely mimics how it works in Linux. Would love to know if this resolves all the issues you've been seeing. On my M1 it pretty consistently uses <30% CPU at ~57 fps.

Mariani-one-shot-timer-4.zip