The softlockup detector currently shows the time spent since the last report. As a result it is not clear whether a CPU is infinitely hogged by a single task or if it is a repeated event. The situation can be simulated with a simply busy loop: while (true) cpu_relax(); The softlockup detector produces: [ 168.277520] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [cat:4865] [ 196.277604] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [cat:4865] [ 236.277522] watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [cat:4865] But it should be, something like: [ 480.372418] watchdog: BUG: soft lockup - CPU#2 stuck for 26s! [cat:4943] [ 508.372359] watchdog: BUG: soft lockup - CPU#2 stuck for 52s! [cat:4943] [ 548.372359] watchdog: BUG: soft lockup - CPU#2 stuck for 89s! [cat:4943] [ 576.372351] watchdog: BUG: soft lockup - CPU#2 stuck for 115s! [cat:4943] For the better output, add an additional timestamp of the last report. Only this timestamp is reset when the watchdog is intentionally touched from slow code paths or when printing the report.
Unified · Split
| @@ -154,7 +154,11 @@ static void lockup_detector_update_enable(void) · 153 unmodified lines | |||
| 154 | 154 | ||
| 155 | #ifdef CONFIG_SOFTLOCKUP_DETECTOR | 155 | #ifdef CONFIG_SOFTLOCKUP_DETECTOR |
| 156 | 156 | ||
| 157 | #define SOFTLOCKUP_RESET ULONG_MAX | 157 | /* |
| 158 | * Delay the soflockup report when running a known slow code. | ||
| 159 | * It does _not_ affect the timestamp of the last successdul reschedule. | ||
| 160 | */ | ||
| 161 | #define SOFTLOCKUP_DELAY_REPORT ULONG_MAX | ||
| 158 | 162 | ||
| 159 | #ifdef CONFIG_SMP | 163 | #ifdef CONFIG_SMP |
| 160 | int __read_mostly sysctl_softlockup_all_cpu_backtrace; | 164 | int __read_mostly sysctl_softlockup_all_cpu_backtrace; |
| @@ -169,7 +173,10 @@ unsigned int __read_mostly softlockup_panic = · 8 unmodified lines | |||
| 169 | static bool softlockup_initialized __read_mostly; | 173 | static bool softlockup_initialized __read_mostly; |
| 170 | static u64 __read_mostly sample_period; | 174 | static u64 __read_mostly sample_period; |
| 171 | 175 | ||
| 176 | /* Timestamp taken after the last successful reschedule. */ | ||
| 172 | static DEFINE_PER_CPU(unsigned long, watchdog_touch_ts); | 177 | static DEFINE_PER_CPU(unsigned long, watchdog_touch_ts); |
| 178 | /* Timestamp of the last softlockup report. */ | ||
| 179 | static DEFINE_PER_CPU(unsigned long, watchdog_report_ts); | ||
| 173 | static DEFINE_PER_CPU(struct hrtimer, watchdog_hrtimer); | 180 | static DEFINE_PER_CPU(struct hrtimer, watchdog_hrtimer); |
| 174 | static DEFINE_PER_CPU(bool, softlockup_touch_sync); | 181 | static DEFINE_PER_CPU(bool, softlockup_touch_sync); |
| 175 | static DEFINE_PER_CPU(bool, soft_watchdog_warn); | 182 | static DEFINE_PER_CPU(bool, soft_watchdog_warn); |
| @@ -235,10 +242,16 @@ static void set_sample_period(void) · 59 unmodified lines | |||
| 235 | watchdog_update_hrtimer_threshold(sample_period); | 242 | watchdog_update_hrtimer_threshold(sample_period); |
| 236 | } | 243 | } |
| 237 | 244 | ||
| 245 | static void update_report_ts(void) | ||
| 246 | { | ||
| 247 | __this_cpu_write(watchdog_report_ts, get_timestamp()); | ||
| 248 | } | ||
| 249 | |||
| 238 | /* Commands for resetting the watchdog */ | 250 | /* Commands for resetting the watchdog */ |
| 239 | static void update_touch_ts(void) | 251 | static void update_touch_ts(void) |
| 240 | { | 252 | { |
| 241 | __this_cpu_write(watchdog_touch_ts, get_timestamp()); | 253 | __this_cpu_write(watchdog_touch_ts, get_timestamp()); |
| 254 | update_report_ts(); | ||
| 242 | } | 255 | } |
| 243 | 256 | ||
| 244 | /** | 257 | /** |
| @@ -252,10 +265,10 @@ static void update_touch_ts(void) · 7 unmodified lines | |||
| 252 | notrace void touch_softlockup_watchdog_sched(void) | 265 | notrace void touch_softlockup_watchdog_sched(void) |
| 253 | { | 266 | { |
| 254 | /* | 267 | /* |
| 255 | * Preemption can be enabled. It doesn't matter which CPU's timestamp | 268 | * Preemption can be enabled. It doesn't matter which CPU's watchdog |
| 256 | * gets zeroed here, so use the raw_ operation. | 269 | * report period gets restarted here, so use the raw_ operation. |
| 257 | */ | 270 | */ |
| 258 | raw_cpu_write(watchdog_touch_ts, SOFTLOCKUP_RESET); | 271 | raw_cpu_write(watchdog_report_ts, SOFTLOCKUP_DELAY_REPORT); |
| 259 | } | 272 | } |
| 260 | 273 | ||
| 261 | notrace void touch_softlockup_watchdog(void) | 274 | notrace void touch_softlockup_watchdog(void) |
| @@ -279,7 +292,7 @@ void touch_all_softlockup_watchdogs(void) · 17 unmodified lines | |||
| 279 | * the softlockup check. | 292 | * the softlockup check. |
| 280 | */ | 293 | */ |
| 281 | for_each_cpu(cpu, &watchdog_allowed_mask) { | 294 | for_each_cpu(cpu, &watchdog_allowed_mask) { |
| 282 | per_cpu(watchdog_touch_ts, cpu) = SOFTLOCKUP_RESET; | 295 | per_cpu(watchdog_report_ts, cpu) = SOFTLOCKUP_DELAY_REPORT; |
| 283 | wq_watchdog_touch(cpu); | 296 | wq_watchdog_touch(cpu); |
| 284 | } | 297 | } |
| 285 | } | 298 | } |
| @@ -287,16 +300,16 @@ void touch_all_softlockup_watchdogs(void) · 1 unmodified line | |||
| 287 | void touch_softlockup_watchdog_sync(void) | 300 | void touch_softlockup_watchdog_sync(void) |
| 288 | { | 301 | { |
| 289 | __this_cpu_write(softlockup_touch_sync, true); | 302 | __this_cpu_write(softlockup_touch_sync, true); |
| 290 | __this_cpu_write(watchdog_touch_ts, SOFTLOCKUP_RESET); | 303 | __this_cpu_write(watchdog_report_ts, SOFTLOCKUP_DELAY_REPORT); |
| 291 | } | 304 | } |
| 292 | 305 | ||
| 293 | static int is_softlockup(unsigned long touch_ts) | 306 | static int is_softlockup(unsigned long touch_ts, unsigned long period_ts) |
| 294 | { | 307 | { |
| 295 | unsigned long now = get_timestamp(); | 308 | unsigned long now = get_timestamp(); |
| 296 | 309 | ||
| 297 | if ((watchdog_enabled & SOFT_WATCHDOG_ENABLED) && watchdog_thresh){ | 310 | if ((watchdog_enabled & SOFT_WATCHDOG_ENABLED) && watchdog_thresh){ |
| 298 | /* Warn about unreasonable delays. */ | 311 | /* Warn about unreasonable delays. */ |
| 299 | if (time_after(now, touch_ts + get_softlockup_thresh())) | 312 | if (time_after(now, period_ts + get_softlockup_thresh())) |
| 300 | return now - touch_ts; | 313 | return now - touch_ts; |
| 301 | } | 314 | } |
| 302 | return 0; | 315 | return 0; |
| @@ -342,6 +355,7 @@ static int softlockup_fn(void *data) · 39 unmodified lines | |||
| 342 | static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) | 355 | static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) |
| 343 | { | 356 | { |
| 344 | unsigned long touch_ts = __this_cpu_read(watchdog_touch_ts); | 357 | unsigned long touch_ts = __this_cpu_read(watchdog_touch_ts); |
| 358 | unsigned long period_ts = __this_cpu_read(watchdog_report_ts); | ||
| 345 | struct pt_regs *regs = get_irq_regs(); | 359 | struct pt_regs *regs = get_irq_regs(); |
| 346 | int duration; | 360 | int duration; |
| 347 | int softlockup_all_cpu_backtrace = sysctl_softlockup_all_cpu_backtrace; | 361 | int softlockup_all_cpu_backtrace = sysctl_softlockup_all_cpu_backtrace; |
| @@ -363,7 +377,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) · 15 unmodified lines | |||
| 363 | /* .. and repeat */ | 377 | /* .. and repeat */ |
| 364 | hrtimer_forward_now(hrtimer, ns_to_ktime(sample_period)); | 378 | hrtimer_forward_now(hrtimer, ns_to_ktime(sample_period)); |
| 365 | 379 | ||
| 366 | if (touch_ts == SOFTLOCKUP_RESET) { | 380 | /* Reset the interval when touched externally by a known slow code. */ |
| 381 | if (period_ts == SOFTLOCKUP_DELAY_REPORT) { | ||
| 367 | if (unlikely(__this_cpu_read(softlockup_touch_sync))) { | 382 | if (unlikely(__this_cpu_read(softlockup_touch_sync))) { |
| 368 | /* | 383 | /* |
| 369 | * If the time stamp was touched atomically | 384 | * If the time stamp was touched atomically |
| @@ -375,7 +390,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) · 5 unmodified lines | |||
| 375 | 390 | ||
| 376 | /* Clear the guest paused flag on watchdog reset */ | 391 | /* Clear the guest paused flag on watchdog reset */ |
| 377 | kvm_check_and_clear_guest_paused(); | 392 | kvm_check_and_clear_guest_paused(); |
| 378 | update_touch_ts(); | 393 | update_report_ts(); |
| 394 | |||
| 379 | return HRTIMER_RESTART; | 395 | return HRTIMER_RESTART; |
| 380 | } | 396 | } |
| 381 | 397 | ||
| @@ -385,7 +401,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) · 3 unmodified lines | |||
| 385 | * indicate it is getting cpu time. If it hasn't then | 401 | * indicate it is getting cpu time. If it hasn't then |
| 386 | * this is a good indication some task is hogging the cpu | 402 | * this is a good indication some task is hogging the cpu |
| 387 | */ | 403 | */ |
| 388 | duration = is_softlockup(touch_ts); | 404 | duration = is_softlockup(touch_ts, period_ts); |
| 389 | if (unlikely(duration)) { | 405 | if (unlikely(duration)) { |
| 390 | /* | 406 | /* |
| 391 | * If a virtual machine is stopped by the host it can look to | 407 | * If a virtual machine is stopped by the host it can look to |
| @@ -411,7 +427,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) · 19 unmodified lines | |||
| 411 | } | 427 | } |
| 412 | 428 | ||
| 413 | /* Start period for the next softlockup warning. */ | 429 | /* Start period for the next softlockup warning. */ |
| 414 | update_touch_ts(); | 430 | update_report_ts(); |
| 415 | 431 | ||
| 416 | pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n", | 432 | pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n", |
| 417 | smp_processor_id(), duration, | 433 | smp_processor_id(), duration, |