Freeboy giving abnormally high CPU loads under certain conditions

[Monospace-V]

Bug Summary

Edited freeboy parameters and created a "chime" sound, and noticed it was giving a very high CPU load.

Steps to reproduce

1. Download this file: Freeboy_issue.mmpz.zip
2. Open and play
3. Look at CPU usage while playing. (Even while muted, apparently, this has an impact on CPU.)

Expected behavior

0 to minimal CPU usage, like with other instruments.

Actual behavior

Goes all the way into orange CPU usage.

Screenshot

Affected LMMS versions

1.2.0, 1.3 alpha

[zonkmachine]

Nice find. On a debug build it triggers an assert.

#4  0x00007fff6fc0ee40 in Gb_Apu::run_until(int) (this=0x7fff6efd0a80, end_time=4)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:131
        __PRETTY_FUNCTION__ = "void Gb_Apu::run_until(blip_time_t)"
#5  0x00007fff6fc0f1c2 in Gb_Apu::write_register(int, unsigned int, int) (this=0x7fff6efd0a80, time=4, addr=65296, data=68)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:208
        __PRETTY_FUNCTION__ = "void Gb_Apu::write_register(blip_time_t, unsigned int, int)"
        reg = 0
        old_reg = 21845

full gdb backtrace

Click to expand

lmms: /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:131: void Gb_Apu::run_until(blip_time_t): Assertion `end_time >= last_time' failed.

Thread 22 "Mixer::fifoWrit" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fff9dd90640 (LWP 29704)]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
49  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt full
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
        set = 
            {__val = {0, 140737319069504, 4222451712, 140735072459264, 140735072459365, 140735072459264, 140735072459264, 140735072459430, 140735072459564, 140735072459264, 140735072459564, 0, 0, 0, 0, 0}}
        pid = 
        tid = 
#1  0x00007ffff5e1d864 in __GI_abort () at abort.c:79
        save_stage = 1
        act = 
          {__sigaction_handler = {sa_handler = 0x7fff70000020, sa_sigaction = 0x7fff70000020}, sa_mask = {__val = {0, 93825006490352, 47244640256, 0, 0, 0, 10866815658275364608, 140735841621936, 18446744073709551336, 11, 140735068329128, 131, 140735068329396, 3, 140737319069608, 140737320424608}}, sa_flags = -169387626, sa_restorer = 0x7fff6fc15590}
        sigs = 
            {__val = {32, 131, 140735068329396, 3, 140735841633856, 140737318965192, 206158430256, 140735841622160, 206158430232, 140735841622160, 140735841621952, 10866815658275364608, 140737488347798, 140737320202031, 140735072459264, 0}}
#2  0x00007ffff5e1d749 in __assert_fail_base
    (fmt=0x7ffff5fa6f78 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7fff6fc155b4 "end_time >= last_time", file=0x7fff6fc154a8 "/home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp", line=131, function=) at assert.c:92
        str = 0x7fff70005a00 "šI\247RU"
        total = 4096
#3  0x00007ffff5e2f3d6 in __GI___assert_fail
    (assertion=0x7fff6fc155b4 "end_time >= last_time", file=0x7fff6fc154a8 "/home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp", line=131, function=0x7fff6fc15590 "void Gb_Apu::run_until(blip_time_t)") at assert.c:101
#4  0x00007fff6fc0ee40 in Gb_Apu::run_until(int) (this=0x7fff6efd0a80, end_time=4)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:131
        __PRETTY_FUNCTION__ = "void Gb_Apu::run_until(blip_time_t)"
#5  0x00007fff6fc0f1c2 in Gb_Apu::write_register(int, unsigned int, int) (this=0x7fff6efd0a80, time=4, addr=65296, data=68)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:208
        __PRETTY_FUNCTION__ = "void Gb_Apu::write_register(blip_time_t, unsigned int, int)"
        reg = 0
        old_reg = 21845
#6  0x00007fff6fc06c84 in FreeBoyInstrument::playNote(NotePlayHandle*, std::array*) (this=
    0x7ffff2770080, _n=0x7ffff26f0c40, _working_buffer=0x7fff6efb1880) at /home/zonkmachine/builds/lmms/plugins/FreeBoy/FreeBoy.cpp:300
        tfp = 0
        samplerate = 44100
        frames = 256
        offset = 0
        data = 68
        freq = 2217
        papu = 0x7fff6efd0a80
        ch3voldata = {0, 3, 2, 1}
        wpm = 0x555558c5c948
        buf_size = 2048
        framesleft = 0
        datalen = 0
        buf = 
          {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -1, -1, -67, -67, -544, -544, -2720, -2720, -5491, -5491, -5492, -5492, -4390, -4390, -5931, -5931,--Type  for more, q to quit, c to continue without paging--
 -9131, -9131, -10336, -10336, -9950, -9950, -9505, -9505, -9098, -9098, -8805, -8805, -8426, -8426, -7933, -7933, -7413, -7413, -6797, -6797, -6094, -6094, -5463, -5463, -4787, -4787, -3638, -3638, -575, -575, 3328, 3328, 4795, 4795, 4371, 4371, 3166, 3166, -23, -23, -3876, -3876, -5377, -5377, -5437, -5437, -5285, -5285, -4967, -4967, -4537, -4537, -3992, -3992, -3557, -3557, -3289, -3289, -3072, -3072, -2866, -2866, -2594, -2594, -2228, -2228, -1473, -1473, 1315, 1315, 4744, 4744, 5808, 5808, 5520, 5520, 4474, 4474, 1234, 1234, -2271, -2271, -3283, -3283, -3259, -3259, -3233, -3233, -3245, -3245, -3310, -3310, -3225, -3225, -3037, -3037, -2797, -2797, -2418, -2418, -1990, -1990, -1609, -1609, -1110, -1110, 242, 242, 3691, 3691, 6911, 6911, 7420, 7420, 6615, 6615, 4792, 4792, 910, 910, -2551, -2551, -3524, -3524, -3608, -3608, -3512, -3512, -3270, -3270, -2894, -2894, -2450, -2450, -2159, -2159, -1999, -1999, -1863, -1863, -1725, -1725, -1478, -1478, -1165, -1165, -20, -20, 3282, 3282, 6109, 6109, 6499, 6499, 6032, 6032, 4359, 4359, 570, 570, -2281, -2281, -2758, -2758, -2753, -2753, -2752, -2752, -2827, -2827, -2887, -2887, -2784, -2784...}
#7  0x0000555555995815 in InstrumentTrack::playNote(NotePlayHandle*, std::array*)
    (this=0x7ffff2713280, n=0x7ffff26f0c40, workingBuffer=0x7fff6efb1880)
    at /home/zonkmachine/builds/lmms/src/tracks/InstrumentTrack.cpp:548

[zonkmachine]

I think it's this up-stream issue: https://bitbucket.org/mpyne/game-music-emu/issues/30/sms_apucpp-assert-of-end_time-last_time Our version is stuck at 21a064e from 2017 and the mentioned issue is from 2019. @tresf Can we update to the latest game-music-emu version? https://bitbucket.org/mpyne/game-music-emu/commits/

[zonkmachine]

I'm testing the latest game-music-emu and I get the same assert. I don't know if our is a separate issue or if we need to update FreeBoy to work with the latest up-stream.

#3  0x00007ffff5e2f3d6 in __GI___assert_fail
    (assertion=0x7fff6f8c15b4 "end_time >= last_time", file=0x7fff6f8c14b0 "/home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp", line=135, function=0x7fff6f8c1590 "void Gb_Apu::run_until(blip_time_t)") at assert.c:101
#4  0x00007fff6f8bae76 in Gb_Apu::run_until(int) (this=0x7fff6eba0080, end_time=4)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:135
        __PRETTY_FUNCTION__ = "void Gb_Apu::run_until(blip_time_t)"
#5  0x00007fff6f8bb1f8 in Gb_Apu::write_register(int, unsigned int, int) (this=0x7fff6eba0080, time=4, addr=65296, data=68)
    at /home/zonkmachine/builds/lmms/plugins/FreeBoy/game-music-emu/gme/Gb_Apu.cpp:212
        __PRETTY_FUNCTION__ = "void Gb_Apu::write_register(blip_time_t, unsigned int, int)"
        reg = 0
        old_reg = 21845

[Monospace-V]

On the forums, Brandy asked if this problem existed with older versions of LMMS. I think these results would be worth looking at.

Checked 0.4.15 because you asked. I don't know what is happening. Sure, Freeboy gives CPU load, but it's mild (in green range, very little CPU load). Then I copied the pattern over to 3O to do a baseline check, and it goes to about double of Freeboy's CPU load. But both are in green range. Therefore testing with 0.4 gives invalid results, whatever the case. BUT the bug doesn't seem to be there. Also checked 1.1.2: Freeboy gives mild CPU load, 3O gives double to triple of that. But both are still in green range. Therefore, I can assume there is no bug. Then, of the four versions I have, freeboy plugin does this only in 1.2.0 and 1.3 alpha.

So I looked at the changelog:

[tresf]

Linking #3618

[zonkmachine]

3618 was backported to stable-1.2 in 587989b1c2b233de29ceb2bea103b14b5c4b6894 and stable-1.2 doesn't crash on a debug build. Not for me anyway.

[zonkmachine]

587989b and stable-1.2 doesn't crash on a debug build.

No, but it's heavier on the cpu definitely. If I revert 587989b there is less load by judging from the cpu meter in lmms and this may not necessarily be a good judge of the actual load.

My thoughts so far.

1. The heavier load seem to be due to later version of game-music-emu. 587989b
2. I've tested the game-music-emu all the way to the first commit of the repo we're using for our submodule. It doesn't go as far way back as our original game-music-emu version so there is code history that still needs to be bisected but I don't know a repo that holds it.
3. Even though FreeBoy is slower in later versions, if you drop another plugin on that track it will still go into the red with most other instruments. It has many notes with long decay. Maybe the switch to a memory manager in 1.2 could have at least a part in this. I'd focus on solving the reason for the assert/crash on debug builds for now.

[Monospace-V]

Since you mentioned it, I checked other plugins with this sequence, and got the following results. I've ordered them in terms of substantiality. Short overview: Organic (bad red, should be looked into), Monstro (yellow), Nescaline (almost yellow).

Screenshots

Organic **(goes even higher into red than FreeBoy does!** This should probably be filed as a separate bug?)
(occurs even in 0.4.15 and 1.1.2)
![image](https://user-images.githubusercontent.com/76674645/131826371-559cb505-c567-4e8d-969d-22951aca99d2.png)

Monstro (yellow)
(1.1.2 as well, as 0.4.15 doesn't have this plugin)
![image](https://user-images.githubusercontent.com/76674645/131826419-c878977b-a1ec-4162-82c2-33d004e177f4.png)

Nescaline (almost yellow)
(1.1.2 as well, as 0.4.15 doesn't have this plugin)
![image](https://user-images.githubusercontent.com/76674645/131826470-daa1b276-3a4a-4594-8be0-dc751667ac4c.png)

3O (green) (used as reference point)
![image](https://user-images.githubusercontent.com/76674645/131826639-4a12854c-f0db-472f-8963-c38056068f48.png)

Other plugins either a) weren't giving more CPU loads than these or b) are simply hosts (for samples, VSTs, etc) and weren't tested.

My PC specifications (results are going to vary depending on CPU)

4 cores
4 logical processes
Base speed: 3.2 GHz
16 GB RAM

[zonkmachine]

Organic (goes even higher into red than FreeBoy does! This should probably be filed as a separate bug?)

No. Organic has a whole lot of oscillators going on. It should be heavier on the system. Try the Vibed plugin and turn on the strings/oscillators one by one and see how it affects the resource use. You also need to understand what game-music-emu, the software pack FreeBoy depends upon, is doing. It is trying to emulate the actual hardware of gameboy and I can't really think of a scenario where it could use less resources (per oscillator) than a plugin based on the native oscillators like Bit Invader or Triple Oscillator. Your demo is only one track but it has a whole lot of notes in it and with a rather long decay. That's the main reason for the high cpu use. Since many of the notes are repeats you could try and recreate the track or at least the effect of it with the use of delay effects tied to the track bpm for lower cpu use.