rtapp execution gives unreliable actual duty cycle

[douglas-raillard-arm]

The following JSON configuration was used on a Juno R0, big core running with "performance" cpufreq governor and idle states disabled:

{
    "tasks": {
        "pelt1": {
            "loop": 1,
            "policy": "SCHED_OTHER",
            "phases": {
                "p000001": {
                    "loop": 125,
                    "run": 8000,
                    "timer": {
                        "ref": "pelt1",
                        "period": 16000
                    },
                    "cpus": [
                        1
                    ]
                }
            },
            "delay": 0
        }
    },
    "global": {
        "duration": -1,
        "calibration": 247,
        "default_policy": "SCHED_OTHER",
        "logstats": false,
        "ftrace": "loop",
        "lock_pages": false
    }

This leads to active time in a period of ~8.5ms in one trace and ~9ms in another, instead of 8 in both.
traces.tar.gz

This may be related to the "loop" ftrace configuration, will update the ticket with further information as they come.

[douglas-raillard-arm]

Actually, it seems more like a calibration issue: rt-app gives very different calibration results from one run to another, but when a good value is found, rt-app seems to execute workloads reliably.

EDIT: both issues are present, and seems to share a common cause

[douglas-raillard-arm]

The known-good version I tried was 482e47a

[vingu-linaro]

Hi Douglas,

I have run on my hikey 20 times : "rt-app doc/examples/template.json" with the master branch and the calibration stays the same: 151ns. I have also checked the log file of the thread, the variation of the duration of the 10msec run event is 18usec.

[vingu-linaro]

I also tried with static link:
The calibration returns 18 times 500ns and 2 times 501ns (obviously the ldexp is not the same) and the variation of the 10msec run event is 123usec.

I also run tests on the big core of hikey960 and the results are quite similar: the calibration always return 138ns and the variation of the 10 msec run event is only 7usec

[douglas-raillard-arm]

Do you see anything strange in the traces I've attached to the issue ?

[vingu-linaro]

i don't see any strange things.
Have you tried to run without enabling trace ? and only using the log file with a memory buffer ?

[douglas-raillard-arm]

Have you tried to run without enabling trace ?

Calibration runs as root without tracing. We just run rt-app with idle states disabled, performance cpufreq gov and the rest of the userspace frozen.

and only using the log file with a memory buffer ?

Do you mean logging to a file in tmpfs, or a specific rt-app option ?

[vingu-linaro]

Have you tried to run without enabling trace ?

Calibration runs as root without tracing. We just run rt-app with idle states disabled, performance cpufreq gov and the rest of the userspace frozen.

and only using the log file with a memory buffer ?

Do you mean logging to a file in tmpfs, or a specific rt-app option ?

"log_size" : 1024, as an example so you will not access file while running events
or even
"log_size" : "disable"

[douglas-raillard-arm]

I'll give it a go. Is that the same logs as enabled by logstats (we disable it) ? Can't find a reference to logstats in the documentation.

Also found that util of the task has some kind of low freq component (~120ms period) with the current rt-app. That happened on CPU1 of my Juno R0, although CPU2 was apparently unaffected (they are the same kind of big core).

[vingu-linaro]

logstats ? Do you mean log_timing() ?
For the low freq component, i will try to reproduce it

[douglas-raillard-arm]

@derkling added "logstats" global option in the JSON produced by LISA, so I assume rt-app knows about it. This is supposed to enable/disable the generation of slack logs, now that they can also be emitted as ftrace events.

Let me know if you are interested in a trace where this strange util variation is observed, and fixed by the change to the busy loop

[vingu-linaro]

There is no "logstats" is master branch sha1: 9a50d76
This raises the question : have you tried the master branch of rt-app ?

[douglas-raillard-arm]

Tests when changing the busy loop were conducted on master @ 9a50d76
So the comparison between rt-app versions with same toolchain are somewhat valid.

But rt-app used within LISA is:

rt-app v1.0-95-g72ab18b (2019-09-05 14:26:07 BST)

This commit SHA1 does not seem to exist in rt-app. @derkling Do you remember if the build of rt-app you upstreamed in LISA ?
EDIT: it's probably 72ab18b (and not g72ab18b), so it's almost the latest master. However, I also cannot find references to logstats in the code ...