Help debugging performance issue.

[taviso]

Hello, I'm trying to run Lotus Agenda 2.0b in DOSEMU2 in terminal mode. It works perfectly, but uses significant CPU while idle. That's stopping my CPU from entering power saving modes, so was hoping I can fix it.

I have other applications I use under DOSEMU that use barely any resources while not actively using them.

If I use -D9+D, I see the log is full of these:

INT21 at ff10:01e8: AX=2afc, BX=0500, CX=0016, DX=cde4, DS=4f9a, ES=b800
INT21 at ff10:01e8: AX=2c02, BX=0500, CX=07e4, DX=0a0d, DS=4f9a, ES=4f9a
INT21 at ff10:01e8: AX=2a36, BX=ffff, CX=3202, DX=2c02, DS=4f9a, ES=6f78
INT21 at ff10:01e8: AX=2c02, BX=ffff, CX=07e4, DX=0a0d, DS=4f9a, ES=4f9a
INT21 at ff10:01e8: AX=2a9a, BX=ce1c, CX=0000, DX=77f7, DS=4f9a, ES=4f9a
INT21 at ff10:01e8: AX=2c02, BX=ce1c, CX=07e4, DX=0a0d, DS=4f9a, ES=4f9a
INT21 at ff10:01e8: AX=2afc, BX=0500, CX=0016, DX=cde4, DS=4f9a, ES=b800
INT21 at ff10:01e8: AX=2c02, BX=0500, CX=07e4, DX=0a0d, DS=4f9a, ES=4f9a
INT21 at ff10:01e8: AX=2a36, BX=ffff, CX=3202, DX=2c02, DS=4f9a, ES=6f78
INT21 at ff10:01e8: AX=2c02, BX=ffff, CX=07e4, DX=0a0d, DS=4f9a, ES=4f9a

I'm not a DOS programmer, do those AH=2A/2C mean Agenda is doing get system time / get system date in some timer interrupt handler?

If I strace the dosemu process, I see it looks like this:

--- SIGALRM {si_signo=SIGALRM, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
futex(0x7fe2835c30a0, FUTEX_WAKE_PRIVATE, 1) = 1
select(1, [0], NULL, NULL, {tv_sec=0, tv_usec=0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=387555, tv_nsec=594799400}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=387555, tv_nsec=594929700}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=387555, tv_nsec=595059600}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=387555, tv_nsec=595189300}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=387555, tv_nsec=595319200}) = 0

There are lots of calls to clock_gettime(), I think that's because rdtsc isn't used on SMP systems, config_post_process() disables it. However, if you have a CPU with invariant/synchronized tsc it should be safe, right?

I tried patching the code to allow rdtsc, and it does seem to work okay.

That got rid of the clock_gettime(), calls and now it looks like this:

--- SIGALRM {si_signo=SIGALRM, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
futex(0x7f2ff2f730a0, FUTEX_WAKE_PRIVATE, 1) = 1
select(1, [0], NULL, NULL, {tv_sec=0, tv_usec=0}) = 0 (Timeout)
gettimeofday({tv_sec=1602606610, tv_usec=615213}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0
gettimeofday({tv_sec=1602606610, tv_usec=615615}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0
gettimeofday({tv_sec=1602606610, tv_usec=615969}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0
gettimeofday({tv_sec=1602606610, tv_usec=616364}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0

I think the stat()s must be the localtime() in get_linux_ticks() checking if the timezone has changed, I can get rid of those by setting the TZ environment variable (e.g. TZ=America/Los_Angeles dosemu -term).

Now it looks like this:

--- SIGALRM {si_signo=SIGALRM, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
futex(0x7f48babe20a0, FUTEX_WAKE_PRIVATE, 1) = 1
select(1, [0], NULL, NULL, {tv_sec=0, tv_usec=0}) = 0 (Timeout)
gettimeofday({tv_sec=1602606824, tv_usec=623312}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=623535}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=623716}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=623895}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=624093}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=624522}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=624725}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=624949}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=625151}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=625353}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=625550}, NULL) = 0
gettimeofday({tv_sec=1602606824, tv_usec=625970}, NULL) = 0

It's a little better, but still using a lot of CPU while idle. Do you have any advice?

Perhaps I can limit how often this timer interrupt fires?

Thanks!

[stsp]

Try something like this:

diff --git a/src/base/core/int.c b/src/base/core/int.c
index 8e7dfeb40..8617aef9e 100644
--- a/src/base/core/int.c
+++ b/src/base/core/int.c
@@ -1112,6 +1112,7 @@ increments AL so we *don't* lose a day if two consecutive 
midnights pass.
     case 0:                    /* read time counter */
        {
            int day_rollover;
+           idle(0, 50, 0, "int1a");
            if (config.timemode == TM_LINUX) {
                /* Set BIOS area flags to LINUX time computed values always */
                last_ticks = get_linux_ticks(0, &day_rollover);

[taviso]

Wow, thanks for the quick response!

I tested it and it is much better, and still seems just as responsive as it did before when using it. That's a huge improvement, it seems to use about 8% CPU when idle, which is a lot more acceptable.

[bartoldeman]

Just to elaborate -- many DOS programs don't care about using 100% CPU when idle, and it wasn't much of an issue at the time they were written. There are some ways however for them to be a bit nicer, the standards are using int28 or int2f/ax=1680 but they are not always used. So DOSEMU implements some heuristics, mainly when the DOS program polls the keyboard or mouse for input. Yours was just a case that wasn't considered yet.

[stsp]

8% is a bug by itself.
I still don't know why dosemu2 eats 6-8%
of CPU when just idling in a command prompt...
Maybe one day someone will find that out.

[taviso]

What do you think about adding a check for the tsc_reliable cpuflag in config_post_process() before overriding config.rdtsc? (The "Denying use of pentium timer on SMP" part).

It seems to help performance a bit for me, and I think it's rare to have unsynchronized tsc anymore (I think that was the concern with SMP).

[stsp]

There were cpus where periodic rdtsc
prevented entering the power-saving modes,
so they were generating a lot of heat in
that mode despite the low cpu load.
But I suppose this is not a problem today.
Please submit a patch for reliable tsc flag.

[stsp]

This regressed all DR-DOS tests, wow!
Andrew, have you looked?

[stsp]

https://travis-ci.com/github/dosemu2/dosemu2/builds/190142718

But now it says "fixed".
Andrew, are these test broken somehow?

[andrewbird]

That test set you point to is the cron and is the only time DR-DOS and FreeDOS 1.20 is tested, so the failure is not specific to the commit it ran on, it could be any commit is the last week that broke it.

[stsp]

Then why it says "fixed" after a new
commit that passes non-cron tests?

[stsp]

OK, last week only you touched mfs
with coverity fixes. :) Strange.

[andrewbird]

cron and is the only time DR-DOS and FreeDOS 1.20 is tested,

So the test set is fixed only because the set didn't include DR-DOS to test against. I guess Travis has no concept of test coverage changing when assigning, fixed, broken, passed labels

OK, last week only you touched mfs
with coverity fixes. :)

I can reproduce here and the problem is the test is hitting a timeout. If I run the test by hand it takes a good while but passes. It seems something generally got slower. I'll try to bisect.

[stsp]

This patch adds delays, so it became
slower from here. Try changing 50 to some
higher value?