History

workqueue: implement lockup detector

Workqueue stalls can happen from a variety of usage bugs such as missing WQ_MEM_RECLAIM flag or concurrency managed work item indefinitely staying RUNNING. These stalls can be extremely difficult to hunt down because the usual warning mechanisms can't detect workqueue stalls and the internal state is pretty opaque. To alleviate the situation, this patch implements workqueue lockup detector. It periodically monitors all worker_pools periodically and, if any pool failed to make forward progress longer than the threshold duration, triggers warning and dumps workqueue state as follows. BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 31s! Showing busy workqueues and worker pools: workqueue events: flags=0x0 pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=17/256 pending: monkey_wrench_fn, e1000_watchdog, cache_reap, vmstat_shepherd, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, release_one_tty, cgroup_release_agent workqueue events_power_efficient: flags=0x80 pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=2/256 pending: check_lifetime, neigh_periodic_work workqueue cgroup_pidlist_destroy: flags=0x0 pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/1 pending: cgroup_pidlist_destroy_work_fn ... The detection mechanism is controller through kernel parameter workqueue.watchdog_thresh and can be updated at runtime through the sysfs module parameter file. v2: Decoupled from softlockup control knobs.

Tejun Heo committed 10 years ago

Commit 82607ad1 parent 03e0d465 files · +200 −3Browse files

Showing the changes to kernel/workqueue.c (1 of 5 files). Show all

Unified · Split

kernel/workqueue.c+171−3
@@ -148,6 +148,8 @@ struct worker_pool { · 147 unmodified lines
148148 int id; /* I: pool ID */
149149 unsigned int flags; /* X: flags */
150150
151+ unsigned long watchdog_ts; /* L: watchdog timestamp */
152+
151153 struct list_head worklist; /* L: list of pending works */
152154 int nr_workers; /* L: total number of workers */
153155
@@ -1083,6 +1085,8 @@ static void pwq_activate_delayed_work(struct work_struct *work) · 929 unmodified lines
10831085 struct pool_workqueue *pwq = get_work_pwq(work);
10841086
10851087 trace_workqueue_activate_work(work);
1088+ if (list_empty(&pwq->pool->worklist))
1089+ pwq->pool->watchdog_ts = jiffies;
10861090 move_linked_works(work, &pwq->pool->worklist, NULL);
10871091 __clear_bit(WORK_STRUCT_DELAYED_BIT, work_data_bits(work));
10881092 pwq->nr_active++;
@@ -1385,6 +1389,8 @@ retry: · 296 unmodified lines
13851389 trace_workqueue_activate_work(work);
13861390 pwq->nr_active++;
13871391 worklist = &pwq->pool->worklist;
1392+ if (list_empty(worklist))
1393+ pwq->pool->watchdog_ts = jiffies;
13881394 } else {
13891395 work_flags |= WORK_STRUCT_DELAYED;
13901396 worklist = &pwq->delayed_works;
@@ -2157,6 +2163,8 @@ recheck: · 766 unmodified lines
21572163 list_first_entry(&pool->worklist,
21582164 struct work_struct, entry);
21592165
2166+ pool->watchdog_ts = jiffies;
2167+
21602168 if (likely(!(*work_data_bits(work) & WORK_STRUCT_LINKED))) {
21612169 /* optimization path, not strictly necessary */
21622170 process_one_work(worker, work);
@@ -2240,6 +2248,7 @@ repeat: · 77 unmodified lines
22402248 struct pool_workqueue, mayday_node);
22412249 struct worker_pool *pool = pwq->pool;
22422250 struct work_struct *work, *n;
2251+ bool first = true;
22432252
22442253 __set_current_state(TASK_RUNNING);
22452254 list_del_init(&pwq->mayday_node);
@@ -2256,9 +2265,14 @@ repeat: · 10 unmodified lines
22562265 * process'em.
22572266 */
22582267 WARN_ON_ONCE(!list_empty(scheduled));
2259− list_for_each_entry_safe(work, n, &pool->worklist, entry)
2260− if (get_work_pwq(work) == pwq)
2268+ list_for_each_entry_safe(work, n, &pool->worklist, entry) {
2269+ if (get_work_pwq(work) == pwq) {
2270+ if (first)
2271+ pool->watchdog_ts = jiffies;
22612272 move_linked_works(work, scheduled, &n);
2273+ }
2274+ first = false;
2275+ }
22622276
22632277 if (!list_empty(scheduled)) {
22642278 process_scheduled_works(rescuer);
@@ -3104,6 +3118,7 @@ static int init_worker_pool(struct worker_pool *pool) · 839 unmodified lines
31043118 pool->cpu = -1;
31053119 pool->node = NUMA_NO_NODE;
31063120 pool->flags |= POOL_DISASSOCIATED;
3121+ pool->watchdog_ts = jiffies;
31073122 INIT_LIST_HEAD(&pool->worklist);
31083123 INIT_LIST_HEAD(&pool->idle_list);
31093124 hash_init(pool->busy_hash);
@@ -4343,7 +4358,9 @@ void show_workqueue_state(void) · 1233 unmodified lines
43434358
43444359 pr_info("pool %d:", pool->id);
43454360 pr_cont_pool_info(pool);
4346− pr_cont(" workers=%d", pool->nr_workers);
4361+ pr_cont(" hung=%us workers=%d",
4362+ jiffies_to_msecs(jiffies - pool->watchdog_ts) / 1000,
4363+ pool->nr_workers);
43474364 if (pool->manager)
43484365 pr_cont(" manager: %d",
43494366 task_pid_nr(pool->manager->task));
@@ -5202,6 +5219,154 @@ static void workqueue_sysfs_unregister(struct workqueue_struct *wq) · 852 unmodified lines
52025219 static void workqueue_sysfs_unregister(struct workqueue_struct *wq) { }
52035220 #endif /* CONFIG_SYSFS */
52045221
5222+/*
5223+ * Workqueue watchdog.
5224+ *
5225+ * Stall may be caused by various bugs - missing WQ_MEM_RECLAIM, illegal
5226+ * flush dependency, a concurrency managed work item which stays RUNNING
5227+ * indefinitely. Workqueue stalls can be very difficult to debug as the
5228+ * usual warning mechanisms don't trigger and internal workqueue state is
5229+ * largely opaque.
5230+ *
5231+ * Workqueue watchdog monitors all worker pools periodically and dumps
5232+ * state if some pools failed to make forward progress for a while where
5233+ * forward progress is defined as the first item on ->worklist changing.
5234+ *
5235+ * This mechanism is controlled through the kernel parameter
5236+ * "workqueue.watchdog_thresh" which can be updated at runtime through the
5237+ * corresponding sysfs parameter file.
5238+ */
5239+#ifdef CONFIG_WQ_WATCHDOG
5240+
5241+static void wq_watchdog_timer_fn(unsigned long data);
5242+
5243+static unsigned long wq_watchdog_thresh = 30;
5244+static struct timer_list wq_watchdog_timer =
5245+ TIMER_DEFERRED_INITIALIZER(wq_watchdog_timer_fn, 0, 0);
5246+
5247+static unsigned long wq_watchdog_touched = INITIAL_JIFFIES;
5248+static DEFINE_PER_CPU(unsigned long, wq_watchdog_touched_cpu) = INITIAL_JIFFIES;
5249+
5250+static void wq_watchdog_reset_touched(void)
5251+{
5252+ int cpu;
5253+
5254+ wq_watchdog_touched = jiffies;
5255+ for_each_possible_cpu(cpu)
5256+ per_cpu(wq_watchdog_touched_cpu, cpu) = jiffies;
5257+}
5258+
5259+static void wq_watchdog_timer_fn(unsigned long data)
5260+{
5261+ unsigned long thresh = READ_ONCE(wq_watchdog_thresh) * HZ;
5262+ bool lockup_detected = false;
5263+ struct worker_pool *pool;
5264+ int pi;
5265+
5266+ if (!thresh)
5267+ return;
5268+
5269+ rcu_read_lock();
5270+
5271+ for_each_pool(pool, pi) {
5272+ unsigned long pool_ts, touched, ts;
5273+
5274+ if (list_empty(&pool->worklist))
5275+ continue;
5276+
5277+ /* get the latest of pool and touched timestamps */
5278+ pool_ts = READ_ONCE(pool->watchdog_ts);
5279+ touched = READ_ONCE(wq_watchdog_touched);
5280+
5281+ if (time_after(pool_ts, touched))
5282+ ts = pool_ts;
5283+ else
5284+ ts = touched;
5285+
5286+ if (pool->cpu >= 0) {
5287+ unsigned long cpu_touched =
5288+ READ_ONCE(per_cpu(wq_watchdog_touched_cpu,
5289+ pool->cpu));
5290+ if (time_after(cpu_touched, ts))
5291+ ts = cpu_touched;
5292+ }
5293+
5294+ /* did we stall? */
5295+ if (time_after(jiffies, ts + thresh)) {
5296+ lockup_detected = true;
5297+ pr_emerg("BUG: workqueue lockup - pool");
5298+ pr_cont_pool_info(pool);
5299+ pr_cont(" stuck for %us!\n",
5300+ jiffies_to_msecs(jiffies - pool_ts) / 1000);
5301+ }
5302+ }
5303+
5304+ rcu_read_unlock();
5305+
5306+ if (lockup_detected)
5307+ show_workqueue_state();
5308+
5309+ wq_watchdog_reset_touched();
5310+ mod_timer(&wq_watchdog_timer, jiffies + thresh);
5311+}
5312+
5313+void wq_watchdog_touch(int cpu)
5314+{
5315+ if (cpu >= 0)
5316+ per_cpu(wq_watchdog_touched_cpu, cpu) = jiffies;
5317+ else
5318+ wq_watchdog_touched = jiffies;
5319+}
5320+
5321+static void wq_watchdog_set_thresh(unsigned long thresh)
5322+{
5323+ wq_watchdog_thresh = 0;
5324+ del_timer_sync(&wq_watchdog_timer);
5325+
5326+ if (thresh) {
5327+ wq_watchdog_thresh = thresh;
5328+ wq_watchdog_reset_touched();
5329+ mod_timer(&wq_watchdog_timer, jiffies + thresh * HZ);
5330+ }
5331+}
5332+
5333+static int wq_watchdog_param_set_thresh(const char *val,
5334+ const struct kernel_param *kp)
5335+{
5336+ unsigned long thresh;
5337+ int ret;
5338+
5339+ ret = kstrtoul(val, 0, &thresh);
5340+ if (ret)
5341+ return ret;
5342+
5343+ if (system_wq)
5344+ wq_watchdog_set_thresh(thresh);
5345+ else
5346+ wq_watchdog_thresh = thresh;
5347+
5348+ return 0;
5349+}
5350+
5351+static const struct kernel_param_ops wq_watchdog_thresh_ops = {
5352+ .set = wq_watchdog_param_set_thresh,
5353+ .get = param_get_ulong,
5354+};
5355+
5356+module_param_cb(watchdog_thresh, &wq_watchdog_thresh_ops, &wq_watchdog_thresh,
5357+ 0644);
5358+
5359+static void wq_watchdog_init(void)
5360+{
5361+ wq_watchdog_set_thresh(wq_watchdog_thresh);
5362+}
5363+
5364+#else /* CONFIG_WQ_WATCHDOG */
5365+
5366+static inline void wq_watchdog_init(void) { }
5367+
5368+#endif /* CONFIG_WQ_WATCHDOG */
5369+
52055370 static void __init wq_numa_init(void)
52065371 {
52075372 cpumask_var_t *tbl;
@@ -5325,6 +5490,9 @@ static int __init init_workqueues(void) · 117 unmodified lines
53255490 !system_unbound_wq || !system_freezable_wq ||
53265491 !system_power_efficient_wq ||
53275492 !system_freezable_power_efficient_wq);
5493+
5494+ wq_watchdog_init();
5495+
53285496 return 0;
53295497 }
53305498 early_initcall(init_workqueues);