Logger: add watchdog to boost its priority in case of a busy-looping task #9404

bkueng · 2018-05-03T10:05:10Z

In case a task with higher prio than the log file writer starts to busy-loop, the log just stops. And since the writer runs at very low prio, most tasks can cause it.
So this PR adds a watchdog that checks from a timer interrupt if the log writer task has been in ready state but has not been scheduled over the last second. This means that someone else is hogging the CPU and we boost the priority of the logger and writer to maximum.
In case the wachdog triggers, logger will also log the CPU load of all running tasks.

The watchdog timeout is fairly low at 1 second. It will only give a false positive if there is a long-running computation of another task without interruption (which we should avoid anyway). But even if it triggers, the system will continue to work fine.

Testing

tested by letting navigator busy-loop after 30 seconds after bootup. Log: https://logs.px4.io/plot_app?log=1b38110f-04e2-4f95-a344-b512b2a3de38
tested on a slow SD card, with high logging rate active: when the writer waits for an SD transfer, it is not in ready state (thus a long logging dropout will not trigger it)
tested with running logger and the writer at max prio with HIL: the vehicle still flies well.

This might help with debugging #9271, since the log stops in-air. There might be different causes for the different reports, and in some cases a busy-looping task could be the cause.

Careful review required.

…allback

…ked for >1s This is to guard against busy-looping tasks, so that we at least have a log. In case the watchdog is triggered, it also logs CPU load of all tasks.

In case a log ends abruptly, we will know that we have everything up to the last second. A test showed that CPU load and the amount of logging drops are unaffected by this.

Helps debugging busy-looping tasks.

avoids compile error on OSX, trying to cast pthread_t to pid_t

dagar · 2018-05-03T16:28:04Z

src/modules/logger/logger.cpp

+			perf_name = "perf_top_preflight";
+			break;
+		case PrintLoadReason::Postflight:
+			perf_name = "perf_top_postflight";


dagar · 2018-05-03T16:29:06Z

I'm curious to see how often this is happens in a regular "good" flight.

dagar · 2018-05-03T16:50:21Z

Is anything else in the system intentionally scheduled at the max priority?

What about restoring the original priority after a relatively long period?

bkueng · 2018-05-04T06:20:30Z

I'm curious to see how often this is happens in a regular "good" flight.

Well, it should not! :)

Is anything else in the system intentionally scheduled at the max priority?

Not that I know of.

What about restoring the original priority after a relatively long period?

I want to keep the logic as simple as possible, as it's something that is supposed to never happen.

davids5

@bkueng This looks good.

I would be concerned about using non ISR safe system resources off the call back.

Also comment about the intentional lack of restore would be helpful.

davids5 · 2018-05-04T10:33:24Z

src/modules/logger/watchdog.cpp

+			static int counter = 0;
+
+			if (++counter > 300) {
+				PX4_ERR("max time in ready: %i ms", (int)max_time / 1000);


Is printf called off of this in interrupt context?

Yes. I thought this was safe?

My recollection is that there is a possibility of a wait on semaphore in the code path of PX4_ERR. Is that not the case?

You are right, printf calls lib_sem_initialize which uses a semaphore. What are you using for such cases?
In any case, thanks for the hint. I removed them now.

PX4_ERR calls printf, which calls lib_sem_initialize, which calls sem_wait

bkueng · 2018-05-07T12:08:08Z

Regarding more frequent fsync calls: I ran a longer test (15min) and checked the dropouts, and I see pretty much the same pattern:

logging rate around 110kb/s
logger status after N seconds/minutes:

new behavior, fsync at least every second:
- 0s: dropouts: 3 (max len: 0.027 s)
- 60s: dropouts: 5 (max len: 0.650 s)
- 5m: dropouts: 36 (max len: 1.133 s)
- 10m:  dropouts: 48 (max len: 1.075 s)
- 15m: dropouts: 49 (max len: 1.150 s)
previous (fsync around 10s):
- 0s: dropouts: 4 (max len: 0.487 s)
- 60s: dropouts: 10 (max len: 0.595 s)
- 5m: dropouts: 36 (max len: 0.832 s)
- 10m: dropouts: 34 (max len: 0.921 s)
- 15m: dropouts: 54 (max len: 0.857 s)

davids5 · 2018-05-07T16:33:59Z

@bkueng what do you attribute the dropouts to?

bkueng · 2018-05-07T16:40:34Z

@bkueng what do you attribute the dropouts to?

I enabled the high-rate logging profile, which considerably increases the logging data rate (around 110kb/s vs around 40kb/s). Plus I used a cheap SD card.

davids5 · 2018-05-07T16:44:52Z

I enabled the high-rate logging profile, which considerably increases the logging data rate (around 110kb/s vs around 40kb/s). Plus I used a cheap SD card.

Does this approach 0 with a high quality card at an adequate rate or is there something we need to have deeper look at?

bkueng · 2018-05-07T16:54:28Z

Does this approach 0 with a high quality card at an adequate rate or is there something we need to have deeper look at?

Yes, I have much less drops with a Sandisk Extreme U3, even with the high-rate logging.

bkueng · 2018-05-09T15:20:20Z

@PX4/testflights can you test this please? And check that logging works as usual.

santiago3dr · 2018-05-09T17:25:50Z

couple flights on a Pixracer (V4) using a typical class 4 SanDisk microSD card
https://logs.px4.io/plot_app?log=12fd5c60-aedf-4f55-84fb-d4f6873e2592
https://logs.px4.io/plot_app?log=84dcdb2c-99e1-4721-8fac-91c158bf8b80

Only issue i encountered was that in the first flight, there was a sudden pause after engaging Position Mode at minute 1:46
I zoom in and see there is an instance of flight mode change which i did not input through the controller

Second flight seemed normal, no issues were observed

Avysuarez · 2018-05-09T20:36:28Z

Flights with pixhawk 2.1 (V3) using SdCard sandisk edge, 8gb, C4.
https://review.px4.io/plot_app?log=8eddc379-e539-4aed-b50f-15249ed73211
https://review.px4.io/plot_app?log=b6cd30f2-3709-44fc-a9e2-7ff0b81a4be9
GOOD FLIGHTS, NO ISSUES!

dannyfpv · 2018-05-09T22:03:08Z

couple flights on a Pixhawkmini (V3) I used a Kingston SD card, class 4, 8GB.
https://logs.px4.io/plot_app?log=0a9c4d4f-9d89-4d4c-aa01-75e42767d29b
https://logs.px4.io/plot_app?log=cf97636d-00da-4c9b-bc1b-054a9aeb58ed
No issues found.

SayanR1 · 2018-05-09T22:55:44Z

Couple flights on a Pixracer (V3) Pixhawk 2 using a no brand 8GB CLASS 4 SD CARD

https://logs.px4.io/plot_app?log=df7cc843-6302-4790-9903-619cab15a079

https://logs.px4.io/plot_app?log=7661a01f-3397-4eac-8543-774d6d0d888e

No Issues during flight.

LorenzMeier · 2018-05-10T08:59:10Z

@bkueng Please review before merging.

bkueng · 2018-05-11T08:05:40Z

I inspected all logs, the watchdog never got triggered.

Only issue i encountered was that in the first flight, there was a sudden pause after engaging Position Mode at minute 1:46

At 1:46, there was a very short commanded (RC stick input change) switch into mission mode, and then back to position. This explains the pause.

bkueng · 2018-05-18T07:20:03Z

@LorenzMeier good to merge?

LorenzMeier · 2018-05-18T20:23:51Z

Thanks, I reviewed the full state and its great, thanks!

bkueng added 6 commits May 3, 2018 11:42

refactor logger: add an enum for the reason of printing the cpu load

658f95a

refactor logger: add struct timer_callback_data_s used in the timer c…

45425b4

…allback

logger: add watchdog that boosts its priority when the writer is bloc…

015d5b1

…ked for >1s This is to guard against busy-looping tasks, so that we at least have a log. In case the watchdog is triggered, it also logs CPU load of all tasks.

logger: ensure that fsync is called at least every second

5d3b455

In case a log ends abruptly, we will know that we have everything up to the last second. A test showed that CPU load and the amount of logging drops are unaffected by this.

top: increase process priority to 255

24db762

Helps debugging busy-looping tasks.

logger: move pthread_t cast to pid_t into watchdog_initialize

a154718

avoids compile error on OSX, trying to cast pthread_t to pid_t

bkueng force-pushed the logger_watchdog branch from 88d47bb to a154718 Compare May 3, 2018 11:41

dagar reviewed May 3, 2018

View reviewed changes

dagar added the Admin: Enhancement (improvement) 💡 label May 3, 2018

dagar added this to the Release v1.8.0 milestone May 3, 2018

dagar requested a review from davids5 May 3, 2018 16:54

davids5 reviewed May 4, 2018

View reviewed changes

thomasgubler assigned bkueng May 4, 2018

logger watchdog: avoid using printf from IRQ context

a949a5d

PX4_ERR calls printf, which calls lib_sem_initialize, which calls sem_wait

LorenzMeier approved these changes May 18, 2018

View reviewed changes

LorenzMeier merged commit 9b5df10 into master May 18, 2018

LorenzMeier deleted the logger_watchdog branch May 18, 2018 20:23

mrpollo mentioned this pull request Jun 5, 2018

v1.8 Changelog scratchpad #9593

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logger: add watchdog to boost its priority in case of a busy-looping task #9404

Logger: add watchdog to boost its priority in case of a busy-looping task #9404

bkueng commented May 3, 2018 •

edited by AuterionWrikeBot

Loading

dagar May 3, 2018

dagar commented May 3, 2018

dagar commented May 3, 2018

bkueng commented May 4, 2018

davids5 left a comment

davids5 May 4, 2018

bkueng May 4, 2018

davids5 May 4, 2018 •

edited

Loading

bkueng May 4, 2018

bkueng May 7, 2018

bkueng commented May 7, 2018

davids5 commented May 7, 2018

bkueng commented May 7, 2018

davids5 commented May 7, 2018

bkueng commented May 7, 2018

bkueng commented May 9, 2018

santiago3dr commented May 9, 2018

Avysuarez commented May 9, 2018

dannyfpv commented May 9, 2018 •

edited by r0gelion

Loading

SayanR1 commented May 9, 2018

LorenzMeier commented May 10, 2018

bkueng commented May 11, 2018

bkueng commented May 18, 2018

LorenzMeier commented May 18, 2018

Logger: add watchdog to boost its priority in case of a busy-looping task #9404

Logger: add watchdog to boost its priority in case of a busy-looping task #9404

Conversation

bkueng commented May 3, 2018 • edited by AuterionWrikeBot Loading

Testing

dagar May 3, 2018

Choose a reason for hiding this comment

dagar commented May 3, 2018

dagar commented May 3, 2018

bkueng commented May 4, 2018

davids5 left a comment

Choose a reason for hiding this comment

davids5 May 4, 2018

Choose a reason for hiding this comment

bkueng May 4, 2018

Choose a reason for hiding this comment

davids5 May 4, 2018 • edited Loading

Choose a reason for hiding this comment

bkueng May 4, 2018

Choose a reason for hiding this comment

bkueng May 7, 2018

Choose a reason for hiding this comment

bkueng commented May 7, 2018

davids5 commented May 7, 2018

bkueng commented May 7, 2018

davids5 commented May 7, 2018

bkueng commented May 7, 2018

bkueng commented May 9, 2018

santiago3dr commented May 9, 2018

Avysuarez commented May 9, 2018

dannyfpv commented May 9, 2018 • edited by r0gelion Loading

SayanR1 commented May 9, 2018

LorenzMeier commented May 10, 2018

bkueng commented May 11, 2018

bkueng commented May 18, 2018

LorenzMeier commented May 18, 2018

bkueng commented May 3, 2018 •

edited by AuterionWrikeBot

Loading

davids5 May 4, 2018 •

edited

Loading

dannyfpv commented May 9, 2018 •

edited by r0gelion

Loading