hc
2023-12-11 6778948f9de86c3cfaf36725a7c87dcff9ba247f
kernel/kernel/printk/printk.c
....@@ -44,9 +44,6 @@
4444 #include <linux/irq_work.h>
4545 #include <linux/ctype.h>
4646 #include <linux/uio.h>
47
-#include <linux/kthread.h>
48
-#include <linux/kdb.h>
49
-#include <linux/clocksource.h>
5047 #include <linux/sched/clock.h>
5148 #include <linux/sched/debug.h>
5249 #include <linux/sched/task_stack.h>
....@@ -64,6 +61,25 @@
6461 #include "printk_ringbuffer.h"
6562 #include "console_cmdline.h"
6663 #include "braille.h"
64
+#include "internal.h"
65
+
66
+#ifdef CONFIG_PRINTK_TIME_FROM_ARM_ARCH_TIMER
67
+#include <clocksource/arm_arch_timer.h>
68
+static u64 get_local_clock(void)
69
+{
70
+ u64 ns;
71
+
72
+ ns = arch_timer_read_counter() * 1000;
73
+ do_div(ns, 24);
74
+
75
+ return ns;
76
+}
77
+#else
78
+static inline u64 get_local_clock(void)
79
+{
80
+ return local_clock();
81
+}
82
+#endif
6783
6884 int console_printk[4] = {
6985 CONSOLE_LOGLEVEL_DEFAULT, /* console_loglevel */
....@@ -232,7 +248,19 @@
232248
233249 static int __down_trylock_console_sem(unsigned long ip)
234250 {
235
- if (down_trylock(&console_sem))
251
+ int lock_failed;
252
+ unsigned long flags;
253
+
254
+ /*
255
+ * Here and in __up_console_sem() we need to be in safe mode,
256
+ * because spindump/WARN/etc from under console ->lock will
257
+ * deadlock in printk()->down_trylock_console_sem() otherwise.
258
+ */
259
+ printk_safe_enter_irqsave(flags);
260
+ lock_failed = down_trylock(&console_sem);
261
+ printk_safe_exit_irqrestore(flags);
262
+
263
+ if (lock_failed)
236264 return 1;
237265 mutex_acquire(&console_lock_dep_map, 0, 1, ip);
238266 return 0;
....@@ -241,9 +269,13 @@
241269
242270 static void __up_console_sem(unsigned long ip)
243271 {
272
+ unsigned long flags;
273
+
244274 mutex_release(&console_lock_dep_map, ip);
245275
276
+ printk_safe_enter_irqsave(flags);
246277 up(&console_sem);
278
+ printk_safe_exit_irqrestore(flags);
247279 }
248280 #define up_console_sem() __up_console_sem(_RET_IP_)
249281
....@@ -256,6 +288,11 @@
256288 * locked without the console sempahore held).
257289 */
258290 static int console_locked, console_suspended;
291
+
292
+/*
293
+ * If exclusive_console is non-NULL then only this console is to be printed to.
294
+ */
295
+static struct console *exclusive_console;
259296
260297 /*
261298 * Array of consoles built from command line options (console=)
....@@ -341,43 +378,61 @@
341378 LOG_CONT = 8, /* text is a fragment of a continuation line */
342379 };
343380
381
+/*
382
+ * The logbuf_lock protects kmsg buffer, indices, counters. This can be taken
383
+ * within the scheduler's rq lock. It must be released before calling
384
+ * console_unlock() or anything else that might wake up a process.
385
+ */
386
+DEFINE_RAW_SPINLOCK(logbuf_lock);
387
+
388
+/*
389
+ * Helper macros to lock/unlock logbuf_lock and switch between
390
+ * printk-safe/unsafe modes.
391
+ */
392
+#define logbuf_lock_irq() \
393
+ do { \
394
+ printk_safe_enter_irq(); \
395
+ raw_spin_lock(&logbuf_lock); \
396
+ } while (0)
397
+
398
+#define logbuf_unlock_irq() \
399
+ do { \
400
+ raw_spin_unlock(&logbuf_lock); \
401
+ printk_safe_exit_irq(); \
402
+ } while (0)
403
+
404
+#define logbuf_lock_irqsave(flags) \
405
+ do { \
406
+ printk_safe_enter_irqsave(flags); \
407
+ raw_spin_lock(&logbuf_lock); \
408
+ } while (0)
409
+
410
+#define logbuf_unlock_irqrestore(flags) \
411
+ do { \
412
+ raw_spin_unlock(&logbuf_lock); \
413
+ printk_safe_exit_irqrestore(flags); \
414
+ } while (0)
415
+
344416 #ifdef CONFIG_PRINTK
345
-/* syslog_lock protects syslog_* variables and write access to clear_seq. */
346
-static DEFINE_SPINLOCK(syslog_lock);
347
-
348
-/* Set to enable sync mode. Once set, it is never cleared. */
349
-static bool sync_mode;
350
-
351417 DECLARE_WAIT_QUEUE_HEAD(log_wait);
352
-/* All 3 protected by @syslog_lock. */
353418 /* the next printk record to read by syslog(READ) or /proc/kmsg */
354419 static u64 syslog_seq;
355420 static size_t syslog_partial;
356421 static bool syslog_time;
357422
358
-struct latched_seq {
359
- seqcount_latch_t latch;
360
- u64 val[2];
361
-};
423
+/* the next printk record to write to the console */
424
+static u64 console_seq;
425
+static u64 exclusive_console_stop_seq;
426
+static unsigned long console_dropped;
362427
363
-/*
364
- * The next printk record to read after the last 'clear' command. There are
365
- * two copies (updated with seqcount_latch) so that reads can locklessly
366
- * access a valid value. Writers are synchronized by @syslog_lock.
367
- */
368
-static struct latched_seq clear_seq = {
369
- .latch = SEQCNT_LATCH_ZERO(clear_seq.latch),
370
- .val[0] = 0,
371
- .val[1] = 0,
372
-};
428
+/* the next printk record to read after the last 'clear' command */
429
+static u64 clear_seq;
373430
374431 #ifdef CONFIG_PRINTK_CALLER
375432 #define PREFIX_MAX 48
376433 #else
377434 #define PREFIX_MAX 32
378435 #endif
379
-
380
-/* the maximum size allowed to be reserved for a record */
381436 #define LOG_LINE_MAX (1024 - PREFIX_MAX)
382437
383438 #define LOG_LEVEL(v) ((v) & 0x07)
....@@ -415,34 +470,9 @@
415470 */
416471 static bool __printk_percpu_data_ready __read_mostly;
417472
418
-static bool printk_percpu_data_ready(void)
473
+bool printk_percpu_data_ready(void)
419474 {
420475 return __printk_percpu_data_ready;
421
-}
422
-
423
-/* Must be called under syslog_lock. */
424
-static void latched_seq_write(struct latched_seq *ls, u64 val)
425
-{
426
- raw_write_seqcount_latch(&ls->latch);
427
- ls->val[0] = val;
428
- raw_write_seqcount_latch(&ls->latch);
429
- ls->val[1] = val;
430
-}
431
-
432
-/* Can be called from any context. */
433
-static u64 latched_seq_read_nolock(struct latched_seq *ls)
434
-{
435
- unsigned int seq;
436
- unsigned int idx;
437
- u64 val;
438
-
439
- do {
440
- seq = raw_read_seqcount_latch(&ls->latch);
441
- idx = seq & 0x1;
442
- val = ls->val[idx];
443
- } while (read_seqcount_latch_retry(&ls->latch, seq));
444
-
445
- return val;
446476 }
447477
448478 /* Return log buffer address */
....@@ -484,6 +514,54 @@
484514 *text_len -= *trunc_msg_len;
485515 else
486516 *trunc_msg_len = 0;
517
+}
518
+
519
+/* insert record into the buffer, discard old ones, update heads */
520
+static int log_store(u32 caller_id, int facility, int level,
521
+ enum log_flags flags, u64 ts_nsec,
522
+ const struct dev_printk_info *dev_info,
523
+ const char *text, u16 text_len)
524
+{
525
+ struct prb_reserved_entry e;
526
+ struct printk_record r;
527
+ u16 trunc_msg_len = 0;
528
+
529
+ prb_rec_init_wr(&r, text_len);
530
+
531
+ if (!prb_reserve(&e, prb, &r)) {
532
+ /* truncate the message if it is too long for empty buffer */
533
+ truncate_msg(&text_len, &trunc_msg_len);
534
+ prb_rec_init_wr(&r, text_len + trunc_msg_len);
535
+ /* survive when the log buffer is too small for trunc_msg */
536
+ if (!prb_reserve(&e, prb, &r))
537
+ return 0;
538
+ }
539
+
540
+ /* fill message */
541
+ memcpy(&r.text_buf[0], text, text_len);
542
+ if (trunc_msg_len)
543
+ memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
544
+ r.info->text_len = text_len + trunc_msg_len;
545
+ r.info->facility = facility;
546
+ r.info->level = level & 7;
547
+ r.info->flags = flags & 0x1f;
548
+ if (ts_nsec > 0)
549
+ r.info->ts_nsec = ts_nsec;
550
+ else
551
+ r.info->ts_nsec = get_local_clock();
552
+ r.info->caller_id = caller_id;
553
+ if (dev_info)
554
+ memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
555
+
556
+ /* A message without a trailing newline can be continued. */
557
+ if (!(flags & LOG_NEWLINE))
558
+ prb_commit(&e);
559
+ else
560
+ prb_final_commit(&e);
561
+
562
+ trace_android_vh_logbuf(prb, &r);
563
+
564
+ return (text_len + trunc_msg_len);
487565 }
488566
489567 int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT);
....@@ -614,7 +692,7 @@
614692
615693 /* /dev/kmsg - userspace message inject/listen interface */
616694 struct devkmsg_user {
617
- atomic64_t seq;
695
+ u64 seq;
618696 struct ratelimit_state rs;
619697 struct mutex lock;
620698 char buf[CONSOLE_EXT_LOG_MAX];
....@@ -715,22 +793,27 @@
715793 if (ret)
716794 return ret;
717795
718
- if (!prb_read_valid(prb, atomic64_read(&user->seq), r)) {
796
+ logbuf_lock_irq();
797
+ if (!prb_read_valid(prb, user->seq, r)) {
719798 if (file->f_flags & O_NONBLOCK) {
720799 ret = -EAGAIN;
800
+ logbuf_unlock_irq();
721801 goto out;
722802 }
723803
804
+ logbuf_unlock_irq();
724805 ret = wait_event_interruptible(log_wait,
725
- prb_read_valid(prb, atomic64_read(&user->seq), r));
806
+ prb_read_valid(prb, user->seq, r));
726807 if (ret)
727808 goto out;
809
+ logbuf_lock_irq();
728810 }
729811
730
- if (r->info->seq != atomic64_read(&user->seq)) {
812
+ if (r->info->seq != user->seq) {
731813 /* our last seen message is gone, return error and reset */
732
- atomic64_set(&user->seq, r->info->seq);
814
+ user->seq = r->info->seq;
733815 ret = -EPIPE;
816
+ logbuf_unlock_irq();
734817 goto out;
735818 }
736819
....@@ -739,7 +822,8 @@
739822 &r->text_buf[0], r->info->text_len,
740823 &r->info->dev_info);
741824
742
- atomic64_set(&user->seq, r->info->seq + 1);
825
+ user->seq = r->info->seq + 1;
826
+ logbuf_unlock_irq();
743827
744828 if (len > count) {
745829 ret = -EINVAL;
....@@ -774,10 +858,11 @@
774858 if (offset)
775859 return -ESPIPE;
776860
861
+ logbuf_lock_irq();
777862 switch (whence) {
778863 case SEEK_SET:
779864 /* the first record */
780
- atomic64_set(&user->seq, prb_first_valid_seq(prb));
865
+ user->seq = prb_first_valid_seq(prb);
781866 break;
782867 case SEEK_DATA:
783868 /*
....@@ -785,15 +870,16 @@
785870 * like issued by 'dmesg -c'. Reading /dev/kmsg itself
786871 * changes no global state, and does not clear anything.
787872 */
788
- atomic64_set(&user->seq, latched_seq_read_nolock(&clear_seq));
873
+ user->seq = clear_seq;
789874 break;
790875 case SEEK_END:
791876 /* after the last record */
792
- atomic64_set(&user->seq, prb_next_seq(prb));
877
+ user->seq = prb_next_seq(prb);
793878 break;
794879 default:
795880 ret = -EINVAL;
796881 }
882
+ logbuf_unlock_irq();
797883 return ret;
798884 }
799885
....@@ -808,13 +894,15 @@
808894
809895 poll_wait(file, &log_wait, wait);
810896
811
- if (prb_read_valid_info(prb, atomic64_read(&user->seq), &info, NULL)) {
897
+ logbuf_lock_irq();
898
+ if (prb_read_valid_info(prb, user->seq, &info, NULL)) {
812899 /* return error when data has vanished underneath us */
813
- if (info.seq != atomic64_read(&user->seq))
900
+ if (info.seq != user->seq)
814901 ret = EPOLLIN|EPOLLRDNORM|EPOLLERR|EPOLLPRI;
815902 else
816903 ret = EPOLLIN|EPOLLRDNORM;
817904 }
905
+ logbuf_unlock_irq();
818906
819907 return ret;
820908 }
....@@ -847,7 +935,9 @@
847935 prb_rec_init_rd(&user->record, &user->info,
848936 &user->text_buf[0], sizeof(user->text_buf));
849937
850
- atomic64_set(&user->seq, prb_first_valid_seq(prb));
938
+ logbuf_lock_irq();
939
+ user->seq = prb_first_valid_seq(prb);
940
+ logbuf_unlock_irq();
851941
852942 file->private_data = user;
853943 return 0;
....@@ -939,9 +1029,6 @@
9391029
9401030 VMCOREINFO_SIZE(atomic_long_t);
9411031 VMCOREINFO_TYPE_OFFSET(atomic_long_t, counter);
942
-
943
- VMCOREINFO_STRUCT_SIZE(latched_seq);
944
- VMCOREINFO_OFFSET(latched_seq, val);
9451032 }
9461033 #endif
9471034
....@@ -1013,6 +1100,9 @@
10131100
10141101 static void __init set_percpu_data_ready(void)
10151102 {
1103
+ printk_safe_init();
1104
+ /* Make sure we set this flag only after printk_safe() init is done */
1105
+ barrier();
10161106 __printk_percpu_data_ready = true;
10171107 }
10181108
....@@ -1052,6 +1142,7 @@
10521142 struct printk_record r;
10531143 size_t new_descs_size;
10541144 size_t new_infos_size;
1145
+ unsigned long flags;
10551146 char *new_log_buf;
10561147 unsigned int free;
10571148 u64 seq;
....@@ -1109,6 +1200,8 @@
11091200 new_descs, ilog2(new_descs_count),
11101201 new_infos);
11111202
1203
+ logbuf_lock_irqsave(flags);
1204
+
11121205 log_buf_len = new_log_buf_len;
11131206 log_buf = new_log_buf;
11141207 new_log_buf_len = 0;
....@@ -1123,6 +1216,8 @@
11231216 * appear during the transition to the dynamic buffer.
11241217 */
11251218 prb = &printk_rb_dynamic;
1219
+
1220
+ logbuf_unlock_irqrestore(flags);
11261221
11271222 if (seq != prb_next_seq(&printk_rb_static)) {
11281223 pr_err("dropped %llu messages\n",
....@@ -1400,50 +1495,6 @@
14001495 return ((prefix_len * line_count) + info->text_len + 1);
14011496 }
14021497
1403
-/*
1404
- * Beginning with @start_seq, find the first record where it and all following
1405
- * records up to (but not including) @max_seq fit into @size.
1406
- *
1407
- * @max_seq is simply an upper bound and does not need to exist. If the caller
1408
- * does not require an upper bound, -1 can be used for @max_seq.
1409
- */
1410
-static u64 find_first_fitting_seq(u64 start_seq, u64 max_seq, size_t size,
1411
- bool syslog, bool time)
1412
-{
1413
- struct printk_info info;
1414
- unsigned int line_count;
1415
- size_t len = 0;
1416
- u64 seq;
1417
-
1418
- /* Determine the size of the records up to @max_seq. */
1419
- prb_for_each_info(start_seq, prb, seq, &info, &line_count) {
1420
- if (info.seq >= max_seq)
1421
- break;
1422
- len += get_record_print_text_size(&info, line_count, syslog, time);
1423
- }
1424
-
1425
- /*
1426
- * Adjust the upper bound for the next loop to avoid subtracting
1427
- * lengths that were never added.
1428
- */
1429
- if (seq < max_seq)
1430
- max_seq = seq;
1431
-
1432
- /*
1433
- * Move first record forward until length fits into the buffer. Ignore
1434
- * newest messages that were not counted in the above cycle. Messages
1435
- * might appear and get lost in the meantime. This is a best effort
1436
- * that prevents an infinite loop that could occur with a retry.
1437
- */
1438
- prb_for_each_info(start_seq, prb, seq, &info, &line_count) {
1439
- if (len <= size || info.seq >= max_seq)
1440
- break;
1441
- len -= get_record_print_text_size(&info, line_count, syslog, time);
1442
- }
1443
-
1444
- return seq;
1445
-}
1446
-
14471498 static int syslog_print(char __user *buf, int size)
14481499 {
14491500 struct printk_info info;
....@@ -1451,19 +1502,19 @@
14511502 char *text;
14521503 int len = 0;
14531504
1454
- text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL);
1505
+ text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
14551506 if (!text)
14561507 return -ENOMEM;
14571508
1458
- prb_rec_init_rd(&r, &info, text, CONSOLE_LOG_MAX);
1509
+ prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX);
14591510
14601511 while (size > 0) {
14611512 size_t n;
14621513 size_t skip;
14631514
1464
- spin_lock_irq(&syslog_lock);
1515
+ logbuf_lock_irq();
14651516 if (!prb_read_valid(prb, syslog_seq, &r)) {
1466
- spin_unlock_irq(&syslog_lock);
1517
+ logbuf_unlock_irq();
14671518 break;
14681519 }
14691520 if (r.info->seq != syslog_seq) {
....@@ -1492,7 +1543,7 @@
14921543 syslog_partial += n;
14931544 } else
14941545 n = 0;
1495
- spin_unlock_irq(&syslog_lock);
1546
+ logbuf_unlock_irq();
14961547
14971548 if (!n)
14981549 break;
....@@ -1515,25 +1566,34 @@
15151566 static int syslog_print_all(char __user *buf, int size, bool clear)
15161567 {
15171568 struct printk_info info;
1569
+ unsigned int line_count;
15181570 struct printk_record r;
15191571 char *text;
15201572 int len = 0;
15211573 u64 seq;
15221574 bool time;
15231575
1524
- text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL);
1576
+ text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
15251577 if (!text)
15261578 return -ENOMEM;
15271579
15281580 time = printk_time;
1581
+ logbuf_lock_irq();
15291582 /*
15301583 * Find first record that fits, including all following records,
15311584 * into the user-provided buffer for this dump.
15321585 */
1533
- seq = find_first_fitting_seq(latched_seq_read_nolock(&clear_seq), -1,
1534
- size, true, time);
1586
+ prb_for_each_info(clear_seq, prb, seq, &info, &line_count)
1587
+ len += get_record_print_text_size(&info, line_count, true, time);
15351588
1536
- prb_rec_init_rd(&r, &info, text, CONSOLE_LOG_MAX);
1589
+ /* move first record forward until length fits into the buffer */
1590
+ prb_for_each_info(clear_seq, prb, seq, &info, &line_count) {
1591
+ if (len <= size)
1592
+ break;
1593
+ len -= get_record_print_text_size(&info, line_count, true, time);
1594
+ }
1595
+
1596
+ prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX);
15371597
15381598 len = 0;
15391599 prb_for_each_record(seq, prb, seq, &r) {
....@@ -1546,20 +1606,20 @@
15461606 break;
15471607 }
15481608
1609
+ logbuf_unlock_irq();
15491610 if (copy_to_user(buf + len, text, textlen))
15501611 len = -EFAULT;
15511612 else
15521613 len += textlen;
1614
+ logbuf_lock_irq();
15531615
15541616 if (len < 0)
15551617 break;
15561618 }
15571619
1558
- if (clear) {
1559
- spin_lock_irq(&syslog_lock);
1560
- latched_seq_write(&clear_seq, seq);
1561
- spin_unlock_irq(&syslog_lock);
1562
- }
1620
+ if (clear)
1621
+ clear_seq = seq;
1622
+ logbuf_unlock_irq();
15631623
15641624 kfree(text);
15651625 return len;
....@@ -1567,21 +1627,9 @@
15671627
15681628 static void syslog_clear(void)
15691629 {
1570
- spin_lock_irq(&syslog_lock);
1571
- latched_seq_write(&clear_seq, prb_next_seq(prb));
1572
- spin_unlock_irq(&syslog_lock);
1573
-}
1574
-
1575
-/* Return a consistent copy of @syslog_seq. */
1576
-static u64 read_syslog_seq_irq(void)
1577
-{
1578
- u64 seq;
1579
-
1580
- spin_lock_irq(&syslog_lock);
1581
- seq = syslog_seq;
1582
- spin_unlock_irq(&syslog_lock);
1583
-
1584
- return seq;
1630
+ logbuf_lock_irq();
1631
+ clear_seq = prb_next_seq(prb);
1632
+ logbuf_unlock_irq();
15851633 }
15861634
15871635 int do_syslog(int type, char __user *buf, int len, int source)
....@@ -1607,9 +1655,8 @@
16071655 return 0;
16081656 if (!access_ok(buf, len))
16091657 return -EFAULT;
1610
-
16111658 error = wait_event_interruptible(log_wait,
1612
- prb_read_valid(prb, read_syslog_seq_irq(), NULL));
1659
+ prb_read_valid(prb, syslog_seq, NULL));
16131660 if (error)
16141661 return error;
16151662 error = syslog_print(buf, len);
....@@ -1657,10 +1704,10 @@
16571704 break;
16581705 /* Number of chars in the log buffer */
16591706 case SYSLOG_ACTION_SIZE_UNREAD:
1660
- spin_lock_irq(&syslog_lock);
1707
+ logbuf_lock_irq();
16611708 if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) {
16621709 /* No unread messages. */
1663
- spin_unlock_irq(&syslog_lock);
1710
+ logbuf_unlock_irq();
16641711 return 0;
16651712 }
16661713 if (info.seq != syslog_seq) {
....@@ -1688,7 +1735,7 @@
16881735 }
16891736 error -= syslog_partial;
16901737 }
1691
- spin_unlock_irq(&syslog_lock);
1738
+ logbuf_unlock_irq();
16921739 break;
16931740 /* Size of the log buffer */
16941741 case SYSLOG_ACTION_SIZE_BUFFER:
....@@ -1707,12 +1754,194 @@
17071754 return do_syslog(type, buf, len, SYSLOG_FROM_READER);
17081755 }
17091756
1757
+/*
1758
+ * Special console_lock variants that help to reduce the risk of soft-lockups.
1759
+ * They allow to pass console_lock to another printk() call using a busy wait.
1760
+ */
1761
+
1762
+#ifdef CONFIG_LOCKDEP
1763
+static struct lockdep_map console_owner_dep_map = {
1764
+ .name = "console_owner"
1765
+};
1766
+#endif
1767
+
1768
+static DEFINE_RAW_SPINLOCK(console_owner_lock);
1769
+static struct task_struct *console_owner;
1770
+static bool console_waiter;
1771
+
1772
+/**
1773
+ * console_lock_spinning_enable - mark beginning of code where another
1774
+ * thread might safely busy wait
1775
+ *
1776
+ * This basically converts console_lock into a spinlock. This marks
1777
+ * the section where the console_lock owner can not sleep, because
1778
+ * there may be a waiter spinning (like a spinlock). Also it must be
1779
+ * ready to hand over the lock at the end of the section.
1780
+ */
1781
+static void console_lock_spinning_enable(void)
1782
+{
1783
+ raw_spin_lock(&console_owner_lock);
1784
+ console_owner = current;
1785
+ raw_spin_unlock(&console_owner_lock);
1786
+
1787
+ /* The waiter may spin on us after setting console_owner */
1788
+ spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
1789
+}
1790
+
1791
+/**
1792
+ * console_lock_spinning_disable_and_check - mark end of code where another
1793
+ * thread was able to busy wait and check if there is a waiter
1794
+ *
1795
+ * This is called at the end of the section where spinning is allowed.
1796
+ * It has two functions. First, it is a signal that it is no longer
1797
+ * safe to start busy waiting for the lock. Second, it checks if
1798
+ * there is a busy waiter and passes the lock rights to her.
1799
+ *
1800
+ * Important: Callers lose the lock if there was a busy waiter.
1801
+ * They must not touch items synchronized by console_lock
1802
+ * in this case.
1803
+ *
1804
+ * Return: 1 if the lock rights were passed, 0 otherwise.
1805
+ */
1806
+static int console_lock_spinning_disable_and_check(void)
1807
+{
1808
+ int waiter;
1809
+
1810
+ raw_spin_lock(&console_owner_lock);
1811
+ waiter = READ_ONCE(console_waiter);
1812
+ console_owner = NULL;
1813
+ raw_spin_unlock(&console_owner_lock);
1814
+
1815
+ if (!waiter) {
1816
+ spin_release(&console_owner_dep_map, _THIS_IP_);
1817
+ return 0;
1818
+ }
1819
+
1820
+ /* The waiter is now free to continue */
1821
+ WRITE_ONCE(console_waiter, false);
1822
+
1823
+ spin_release(&console_owner_dep_map, _THIS_IP_);
1824
+
1825
+ /*
1826
+ * Hand off console_lock to waiter. The waiter will perform
1827
+ * the up(). After this, the waiter is the console_lock owner.
1828
+ */
1829
+ mutex_release(&console_lock_dep_map, _THIS_IP_);
1830
+ return 1;
1831
+}
1832
+
1833
+/**
1834
+ * console_trylock_spinning - try to get console_lock by busy waiting
1835
+ *
1836
+ * This allows to busy wait for the console_lock when the current
1837
+ * owner is running in specially marked sections. It means that
1838
+ * the current owner is running and cannot reschedule until it
1839
+ * is ready to lose the lock.
1840
+ *
1841
+ * Return: 1 if we got the lock, 0 othrewise
1842
+ */
1843
+static int console_trylock_spinning(void)
1844
+{
1845
+ struct task_struct *owner = NULL;
1846
+ bool waiter;
1847
+ bool spin = false;
1848
+ unsigned long flags;
1849
+
1850
+ if (console_trylock())
1851
+ return 1;
1852
+
1853
+ printk_safe_enter_irqsave(flags);
1854
+
1855
+ raw_spin_lock(&console_owner_lock);
1856
+ owner = READ_ONCE(console_owner);
1857
+ waiter = READ_ONCE(console_waiter);
1858
+ if (!waiter && owner && owner != current) {
1859
+ WRITE_ONCE(console_waiter, true);
1860
+ spin = true;
1861
+ }
1862
+ raw_spin_unlock(&console_owner_lock);
1863
+
1864
+ /*
1865
+ * If there is an active printk() writing to the
1866
+ * consoles, instead of having it write our data too,
1867
+ * see if we can offload that load from the active
1868
+ * printer, and do some printing ourselves.
1869
+ * Go into a spin only if there isn't already a waiter
1870
+ * spinning, and there is an active printer, and
1871
+ * that active printer isn't us (recursive printk?).
1872
+ */
1873
+ if (!spin) {
1874
+ printk_safe_exit_irqrestore(flags);
1875
+ return 0;
1876
+ }
1877
+
1878
+ /* We spin waiting for the owner to release us */
1879
+ spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
1880
+ /* Owner will clear console_waiter on hand off */
1881
+ while (READ_ONCE(console_waiter))
1882
+ cpu_relax();
1883
+ spin_release(&console_owner_dep_map, _THIS_IP_);
1884
+
1885
+ printk_safe_exit_irqrestore(flags);
1886
+ /*
1887
+ * The owner passed the console lock to us.
1888
+ * Since we did not spin on console lock, annotate
1889
+ * this as a trylock. Otherwise lockdep will
1890
+ * complain.
1891
+ */
1892
+ mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
1893
+
1894
+ return 1;
1895
+}
1896
+
1897
+/*
1898
+ * Call the console drivers, asking them to write out
1899
+ * log_buf[start] to log_buf[end - 1].
1900
+ * The console_lock must be held.
1901
+ */
1902
+static void call_console_drivers(const char *ext_text, size_t ext_len,
1903
+ const char *text, size_t len)
1904
+{
1905
+ static char dropped_text[64];
1906
+ size_t dropped_len = 0;
1907
+ struct console *con;
1908
+
1909
+ trace_console_rcuidle(text, len);
1910
+
1911
+ if (!console_drivers)
1912
+ return;
1913
+
1914
+ if (console_dropped) {
1915
+ dropped_len = snprintf(dropped_text, sizeof(dropped_text),
1916
+ "** %lu printk messages dropped **\n",
1917
+ console_dropped);
1918
+ console_dropped = 0;
1919
+ }
1920
+
1921
+ for_each_console(con) {
1922
+ if (exclusive_console && con != exclusive_console)
1923
+ continue;
1924
+ if (!(con->flags & CON_ENABLED))
1925
+ continue;
1926
+ if (!con->write)
1927
+ continue;
1928
+ if (!cpu_online(smp_processor_id()) &&
1929
+ !(con->flags & CON_ANYTIME))
1930
+ continue;
1931
+ if (con->flags & CON_EXTENDED)
1932
+ con->write(con, ext_text, ext_len);
1933
+ else {
1934
+ if (dropped_len)
1935
+ con->write(con, dropped_text, dropped_len);
1936
+ con->write(con, text, len);
1937
+ }
1938
+ }
1939
+}
1940
+
17101941 int printk_delay_msec __read_mostly;
17111942
1712
-static inline void printk_delay(int level)
1943
+static inline void printk_delay(void)
17131944 {
1714
- boot_delay_msec(level);
1715
-
17161945 if (unlikely(printk_delay_msec)) {
17171946 int m = printk_delay_msec;
17181947
....@@ -1723,282 +1952,83 @@
17231952 }
17241953 }
17251954
1726
-static bool kernel_sync_mode(void)
1727
-{
1728
- return (oops_in_progress || sync_mode);
1729
-}
1730
-
1731
-static bool console_can_sync(struct console *con)
1732
-{
1733
- if (!(con->flags & CON_ENABLED))
1734
- return false;
1735
- if (con->write_atomic && kernel_sync_mode())
1736
- return true;
1737
- if (con->write_atomic && (con->flags & CON_HANDOVER) && !con->thread)
1738
- return true;
1739
- if (con->write && (con->flags & CON_BOOT) && !con->thread)
1740
- return true;
1741
- return false;
1742
-}
1743
-
1744
-static bool call_sync_console_driver(struct console *con, const char *text, size_t text_len)
1745
-{
1746
- if (!(con->flags & CON_ENABLED))
1747
- return false;
1748
- if (con->write_atomic && kernel_sync_mode())
1749
- con->write_atomic(con, text, text_len);
1750
- else if (con->write_atomic && (con->flags & CON_HANDOVER) && !con->thread)
1751
- con->write_atomic(con, text, text_len);
1752
- else if (con->write && (con->flags & CON_BOOT) && !con->thread)
1753
- con->write(con, text, text_len);
1754
- else
1755
- return false;
1756
-
1757
- return true;
1758
-}
1759
-
1760
-static bool have_atomic_console(void)
1761
-{
1762
- struct console *con;
1763
-
1764
- for_each_console(con) {
1765
- if (!(con->flags & CON_ENABLED))
1766
- continue;
1767
- if (con->write_atomic)
1768
- return true;
1769
- }
1770
- return false;
1771
-}
1772
-
1773
-static bool print_sync(struct console *con, u64 *seq)
1774
-{
1775
- struct printk_info info;
1776
- struct printk_record r;
1777
- size_t text_len;
1778
-
1779
- prb_rec_init_rd(&r, &info, &con->sync_buf[0], sizeof(con->sync_buf));
1780
-
1781
- if (!prb_read_valid(prb, *seq, &r))
1782
- return false;
1783
-
1784
- text_len = record_print_text(&r, console_msg_format & MSG_FORMAT_SYSLOG, printk_time);
1785
-
1786
- if (!call_sync_console_driver(con, &con->sync_buf[0], text_len))
1787
- return false;
1788
-
1789
- *seq = r.info->seq;
1790
-
1791
- touch_softlockup_watchdog_sync();
1792
- clocksource_touch_watchdog();
1793
- rcu_cpu_stall_reset();
1794
- touch_nmi_watchdog();
1795
-
1796
- if (text_len)
1797
- printk_delay(r.info->level);
1798
-
1799
- return true;
1800
-}
1801
-
1802
-static void print_sync_until(struct console *con, u64 seq)
1803
-{
1804
- unsigned int flags;
1805
- u64 printk_seq;
1806
-
1807
- console_atomic_lock(&flags);
1808
- for (;;) {
1809
- printk_seq = atomic64_read(&con->printk_seq);
1810
- if (printk_seq >= seq)
1811
- break;
1812
- if (!print_sync(con, &printk_seq))
1813
- break;
1814
- atomic64_set(&con->printk_seq, printk_seq + 1);
1815
- }
1816
- console_atomic_unlock(flags);
1817
-}
1818
-
1819
-#ifdef CONFIG_PRINTK_NMI
1820
-#define NUM_RECURSION_CTX 2
1821
-#else
1822
-#define NUM_RECURSION_CTX 1
1823
-#endif
1824
-
1825
-struct printk_recursion {
1826
- char count[NUM_RECURSION_CTX];
1827
-};
1828
-
1829
-static DEFINE_PER_CPU(struct printk_recursion, percpu_printk_recursion);
1830
-static char printk_recursion_count[NUM_RECURSION_CTX];
1831
-
1832
-static char *printk_recursion_counter(void)
1833
-{
1834
- struct printk_recursion *rec;
1835
- char *count;
1836
-
1837
- if (!printk_percpu_data_ready()) {
1838
- count = &printk_recursion_count[0];
1839
- } else {
1840
- rec = this_cpu_ptr(&percpu_printk_recursion);
1841
-
1842
- count = &rec->count[0];
1843
- }
1844
-
1845
-#ifdef CONFIG_PRINTK_NMI
1846
- if (in_nmi())
1847
- count++;
1848
-#endif
1849
-
1850
- return count;
1851
-}
1852
-
1853
-static bool printk_enter_irqsave(unsigned long *flags)
1854
-{
1855
- char *count;
1856
-
1857
- local_irq_save(*flags);
1858
- count = printk_recursion_counter();
1859
- /* Only 1 level of recursion allowed. */
1860
- if (*count > 1) {
1861
- local_irq_restore(*flags);
1862
- return false;
1863
- }
1864
- (*count)++;
1865
-
1866
- return true;
1867
-}
1868
-
1869
-static void printk_exit_irqrestore(unsigned long flags)
1870
-{
1871
- char *count;
1872
-
1873
- count = printk_recursion_counter();
1874
- (*count)--;
1875
- local_irq_restore(flags);
1876
-}
1877
-
18781955 static inline u32 printk_caller_id(void)
18791956 {
18801957 return in_task() ? task_pid_nr(current) :
18811958 0x80000000 + raw_smp_processor_id();
18821959 }
18831960
1884
-/**
1885
- * parse_prefix - Parse level and control flags.
1886
- *
1887
- * @text: The terminated text message.
1888
- * @level: A pointer to the current level value, will be updated.
1889
- * @lflags: A pointer to the current log flags, will be updated.
1890
- *
1891
- * @level may be NULL if the caller is not interested in the parsed value.
1892
- * Otherwise the variable pointed to by @level must be set to
1893
- * LOGLEVEL_DEFAULT in order to be updated with the parsed value.
1894
- *
1895
- * @lflags may be NULL if the caller is not interested in the parsed value.
1896
- * Otherwise the variable pointed to by @lflags will be OR'd with the parsed
1897
- * value.
1898
- *
1899
- * Return: The length of the parsed level and control flags.
1900
- */
1901
-static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
1902
-{
1903
- u16 prefix_len = 0;
1904
- int kern_level;
1905
-
1906
- while (*text) {
1907
- kern_level = printk_get_level(text);
1908
- if (!kern_level)
1909
- break;
1910
-
1911
- switch (kern_level) {
1912
- case '0' ... '7':
1913
- if (level && *level == LOGLEVEL_DEFAULT)
1914
- *level = kern_level - '0';
1915
- break;
1916
- case 'c': /* KERN_CONT */
1917
- if (lflags)
1918
- *lflags |= LOG_CONT;
1919
- }
1920
-
1921
- prefix_len += 2;
1922
- text += 2;
1923
- }
1924
-
1925
- return prefix_len;
1926
-}
1927
-
1928
-static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags,
1929
- const char *fmt, va_list args)
1930
-{
1931
- u16 text_len;
1932
-
1933
- text_len = vscnprintf(text, size, fmt, args);
1934
-
1935
- /* Mark and strip a trailing newline. */
1936
- if (text_len && text[text_len - 1] == '\n') {
1937
- text_len--;
1938
- *lflags |= LOG_NEWLINE;
1939
- }
1940
-
1941
- /* Strip log level and control flags. */
1942
- if (facility == 0) {
1943
- u16 prefix_len;
1944
-
1945
- prefix_len = parse_prefix(text, NULL, NULL);
1946
- if (prefix_len) {
1947
- text_len -= prefix_len;
1948
- memmove(text, text + prefix_len, text_len);
1949
- }
1950
- }
1951
-
1952
- return text_len;
1953
-}
1954
-
1955
-__printf(4, 0)
1956
-static int vprintk_store(int facility, int level,
1961
+static size_t log_output(int facility, int level, enum log_flags lflags,
19571962 const struct dev_printk_info *dev_info,
1958
- const char *fmt, va_list args)
1963
+ char *text, size_t text_len)
19591964 {
19601965 const u32 caller_id = printk_caller_id();
1961
- struct prb_reserved_entry e;
1966
+
1967
+ if (lflags & LOG_CONT) {
1968
+ struct prb_reserved_entry e;
1969
+ struct printk_record r;
1970
+
1971
+ prb_rec_init_wr(&r, text_len);
1972
+ if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
1973
+ memcpy(&r.text_buf[r.info->text_len], text, text_len);
1974
+ r.info->text_len += text_len;
1975
+ if (lflags & LOG_NEWLINE) {
1976
+ r.info->flags |= LOG_NEWLINE;
1977
+ prb_final_commit(&e);
1978
+ } else {
1979
+ prb_commit(&e);
1980
+ }
1981
+
1982
+ trace_android_vh_logbuf_pr_cont(&r, text_len);
1983
+ return text_len;
1984
+ }
1985
+ }
1986
+
1987
+ /* Store it in the record log */
1988
+ return log_store(caller_id, facility, level, lflags, 0,
1989
+ dev_info, text, text_len);
1990
+}
1991
+
1992
+/* Must be called under logbuf_lock. */
1993
+int vprintk_store(int facility, int level,
1994
+ const struct dev_printk_info *dev_info,
1995
+ const char *fmt, va_list args)
1996
+{
1997
+ static char textbuf[LOG_LINE_MAX];
1998
+ char *text = textbuf;
1999
+ size_t text_len;
19622000 enum log_flags lflags = 0;
1963
- bool final_commit = false;
1964
- struct printk_record r;
1965
- unsigned long irqflags;
1966
- u16 trunc_msg_len = 0;
1967
- char prefix_buf[8];
1968
- u16 reserve_size;
1969
- va_list args2;
1970
- u16 text_len;
1971
- int ret = 0;
1972
- u64 ts_nsec;
1973
- u64 seq;
19742001
19752002 /*
1976
- * Since the duration of printk() can vary depending on the message
1977
- * and state of the ringbuffer, grab the timestamp now so that it is
1978
- * close to the call of printk(). This provides a more deterministic
1979
- * timestamp with respect to the caller.
2003
+ * The printf needs to come first; we need the syslog
2004
+ * prefix which might be passed-in as a parameter.
19802005 */
1981
- ts_nsec = local_clock();
2006
+ text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
19822007
1983
- if (!printk_enter_irqsave(&irqflags))
1984
- return 0;
2008
+ /* mark and strip a trailing newline */
2009
+ if (text_len && text[text_len-1] == '\n') {
2010
+ text_len--;
2011
+ lflags |= LOG_NEWLINE;
2012
+ }
19852013
1986
- /*
1987
- * The sprintf needs to come first since the syslog prefix might be
1988
- * passed in as a parameter. An extra byte must be reserved so that
1989
- * later the vscnprintf() into the reserved buffer has room for the
1990
- * terminating '\0', which is not counted by vsnprintf().
1991
- */
1992
- va_copy(args2, args);
1993
- reserve_size = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args2) + 1;
1994
- va_end(args2);
2014
+ /* strip kernel syslog prefix and extract log level or control flags */
2015
+ if (facility == 0) {
2016
+ int kern_level;
19952017
1996
- if (reserve_size > LOG_LINE_MAX)
1997
- reserve_size = LOG_LINE_MAX;
2018
+ while ((kern_level = printk_get_level(text)) != 0) {
2019
+ switch (kern_level) {
2020
+ case '0' ... '7':
2021
+ if (level == LOGLEVEL_DEFAULT)
2022
+ level = kern_level - '0';
2023
+ break;
2024
+ case 'c': /* KERN_CONT */
2025
+ lflags |= LOG_CONT;
2026
+ }
19982027
1999
- /* Extract log level or control flags. */
2000
- if (facility == 0)
2001
- parse_prefix(&prefix_buf[0], &level, &lflags);
2028
+ text_len -= 2;
2029
+ text += 2;
2030
+ }
2031
+ }
20022032
20032033 if (level == LOGLEVEL_DEFAULT)
20042034 level = default_message_loglevel;
....@@ -2006,79 +2036,7 @@
20062036 if (dev_info)
20072037 lflags |= LOG_NEWLINE;
20082038
2009
- if (lflags & LOG_CONT) {
2010
- prb_rec_init_wr(&r, reserve_size);
2011
- if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
2012
- seq = r.info->seq;
2013
- text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size,
2014
- facility, &lflags, fmt, args);
2015
- r.info->text_len += text_len;
2016
-
2017
- if (lflags & LOG_NEWLINE) {
2018
- r.info->flags |= LOG_NEWLINE;
2019
- prb_final_commit(&e);
2020
- final_commit = true;
2021
- } else {
2022
- prb_commit(&e);
2023
- }
2024
-
2025
- ret = text_len;
2026
- goto out;
2027
- }
2028
- }
2029
-
2030
- /*
2031
- * Explicitly initialize the record before every prb_reserve() call.
2032
- * prb_reserve_in_last() and prb_reserve() purposely invalidate the
2033
- * structure when they fail.
2034
- */
2035
- prb_rec_init_wr(&r, reserve_size);
2036
- if (!prb_reserve(&e, prb, &r)) {
2037
- /* truncate the message if it is too long for empty buffer */
2038
- truncate_msg(&reserve_size, &trunc_msg_len);
2039
-
2040
- prb_rec_init_wr(&r, reserve_size + trunc_msg_len);
2041
- if (!prb_reserve(&e, prb, &r))
2042
- goto out;
2043
- }
2044
-
2045
- seq = r.info->seq;
2046
-
2047
- /* fill message */
2048
- text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &lflags, fmt, args);
2049
- if (trunc_msg_len)
2050
- memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
2051
- r.info->text_len = text_len + trunc_msg_len;
2052
- r.info->facility = facility;
2053
- r.info->level = level & 7;
2054
- r.info->flags = lflags & 0x1f;
2055
- r.info->ts_nsec = ts_nsec;
2056
- r.info->caller_id = caller_id;
2057
- if (dev_info)
2058
- memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
2059
-
2060
- /* A message without a trailing newline can be continued. */
2061
- if (!(lflags & LOG_NEWLINE)) {
2062
- prb_commit(&e);
2063
- } else {
2064
- prb_final_commit(&e);
2065
- final_commit = true;
2066
- }
2067
-
2068
- ret = text_len + trunc_msg_len;
2069
-out:
2070
- /* only the kernel may perform synchronous printing */
2071
- if (facility == 0 && final_commit) {
2072
- struct console *con;
2073
-
2074
- for_each_console(con) {
2075
- if (console_can_sync(con))
2076
- print_sync_until(con, seq + 1);
2077
- }
2078
- }
2079
-
2080
- printk_exit_irqrestore(irqflags);
2081
- return ret;
2039
+ return log_output(facility, level, lflags, dev_info, text, text_len);
20822040 }
20832041
20842042 asmlinkage int vprintk_emit(int facility, int level,
....@@ -2086,42 +2044,60 @@
20862044 const char *fmt, va_list args)
20872045 {
20882046 int printed_len;
2047
+ bool in_sched = false;
2048
+ unsigned long flags;
20892049
20902050 /* Suppress unimportant messages after panic happens */
20912051 if (unlikely(suppress_printk))
20922052 return 0;
20932053
2094
- if (level == LOGLEVEL_SCHED)
2054
+ if (level == LOGLEVEL_SCHED) {
20952055 level = LOGLEVEL_DEFAULT;
2056
+ in_sched = true;
2057
+ }
20962058
2059
+ boot_delay_msec(level);
2060
+ printk_delay();
2061
+
2062
+ /* This stops the holder of console_sem just where we want him */
2063
+ logbuf_lock_irqsave(flags);
20972064 printed_len = vprintk_store(facility, level, dev_info, fmt, args);
2065
+ logbuf_unlock_irqrestore(flags);
2066
+
2067
+ /* If called from the scheduler, we can not call up(). */
2068
+ if (!in_sched) {
2069
+ /*
2070
+ * Disable preemption to avoid being preempted while holding
2071
+ * console_sem which would prevent anyone from printing to
2072
+ * console
2073
+ */
2074
+ preempt_disable();
2075
+ /*
2076
+ * Try to acquire and then immediately release the console
2077
+ * semaphore. The release will print out buffers and wake up
2078
+ * /dev/kmsg and syslog() users.
2079
+ */
2080
+ if (console_trylock_spinning())
2081
+ console_unlock();
2082
+ preempt_enable();
2083
+ }
20982084
20992085 wake_up_klogd();
21002086 return printed_len;
21012087 }
21022088 EXPORT_SYMBOL(vprintk_emit);
21032089
2104
-__printf(1, 0)
2105
-static int vprintk_default(const char *fmt, va_list args)
2106
-{
2107
- return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
2108
-}
2109
-__printf(1, 0)
2110
-static int vprintk_func(const char *fmt, va_list args)
2111
-{
2112
-#ifdef CONFIG_KGDB_KDB
2113
- /* Allow to pass printk() to kdb but avoid a recursion. */
2114
- if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
2115
- return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
2116
-#endif
2117
- return vprintk_default(fmt, args);
2118
-}
2119
-
21202090 asmlinkage int vprintk(const char *fmt, va_list args)
21212091 {
21222092 return vprintk_func(fmt, args);
21232093 }
21242094 EXPORT_SYMBOL(vprintk);
2095
+
2096
+int vprintk_default(const char *fmt, va_list args)
2097
+{
2098
+ return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
2099
+}
2100
+EXPORT_SYMBOL_GPL(vprintk_default);
21252101
21262102 /**
21272103 * printk - print a kernel message
....@@ -2157,162 +2133,38 @@
21572133 }
21582134 EXPORT_SYMBOL(printk);
21592135
2160
-static int printk_kthread_func(void *data)
2161
-{
2162
- struct console *con = data;
2163
- unsigned long dropped = 0;
2164
- char *dropped_text = NULL;
2165
- struct printk_info info;
2166
- struct printk_record r;
2167
- char *ext_text = NULL;
2168
- size_t dropped_len;
2169
- int ret = -ENOMEM;
2170
- char *text = NULL;
2171
- char *write_text;
2172
- u64 printk_seq;
2173
- size_t len;
2174
- int error;
2175
- u64 seq;
2176
-
2177
- if (con->flags & CON_EXTENDED) {
2178
- ext_text = kmalloc(CONSOLE_EXT_LOG_MAX, GFP_KERNEL);
2179
- if (!ext_text)
2180
- goto out;
2181
- }
2182
- text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
2183
- dropped_text = kmalloc(64, GFP_KERNEL);
2184
- if (!text || !dropped_text)
2185
- goto out;
2186
-
2187
- if (con->flags & CON_EXTENDED)
2188
- write_text = ext_text;
2189
- else
2190
- write_text = text;
2191
-
2192
- seq = atomic64_read(&con->printk_seq);
2193
-
2194
- prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX);
2195
-
2196
- for (;;) {
2197
- error = wait_event_interruptible(log_wait,
2198
- prb_read_valid(prb, seq, &r) || kthread_should_stop());
2199
-
2200
- if (kthread_should_stop())
2201
- break;
2202
-
2203
- if (error)
2204
- continue;
2205
-
2206
- if (seq != r.info->seq) {
2207
- dropped += r.info->seq - seq;
2208
- seq = r.info->seq;
2209
- }
2210
-
2211
- seq++;
2212
-
2213
- if (!(con->flags & CON_ENABLED))
2214
- continue;
2215
-
2216
- if (suppress_message_printing(r.info->level))
2217
- continue;
2218
-
2219
- if (con->flags & CON_EXTENDED) {
2220
- len = info_print_ext_header(ext_text,
2221
- CONSOLE_EXT_LOG_MAX,
2222
- r.info);
2223
- len += msg_print_ext_body(ext_text + len,
2224
- CONSOLE_EXT_LOG_MAX - len,
2225
- &r.text_buf[0], r.info->text_len,
2226
- &r.info->dev_info);
2227
- } else {
2228
- len = record_print_text(&r,
2229
- console_msg_format & MSG_FORMAT_SYSLOG,
2230
- printk_time);
2231
- }
2232
-
2233
- printk_seq = atomic64_read(&con->printk_seq);
2234
-
2235
- console_lock();
2236
- console_may_schedule = 0;
2237
-
2238
- if (kernel_sync_mode() && con->write_atomic) {
2239
- console_unlock();
2240
- break;
2241
- }
2242
-
2243
- if (!(con->flags & CON_EXTENDED) && dropped) {
2244
- dropped_len = snprintf(dropped_text, 64,
2245
- "** %lu printk messages dropped **\n",
2246
- dropped);
2247
- dropped = 0;
2248
-
2249
- con->write(con, dropped_text, dropped_len);
2250
- printk_delay(r.info->level);
2251
- }
2252
-
2253
- con->write(con, write_text, len);
2254
- if (len)
2255
- printk_delay(r.info->level);
2256
-
2257
- atomic64_cmpxchg_relaxed(&con->printk_seq, printk_seq, seq);
2258
-
2259
- console_unlock();
2260
- }
2261
-out:
2262
- kfree(dropped_text);
2263
- kfree(text);
2264
- kfree(ext_text);
2265
- pr_info("%sconsole [%s%d]: printing thread stopped\n",
2266
- (con->flags & CON_BOOT) ? "boot" : "",
2267
- con->name, con->index);
2268
- return ret;
2269
-}
2270
-
2271
-/* Must be called within console_lock(). */
2272
-static void start_printk_kthread(struct console *con)
2273
-{
2274
- /* No need to start a printing thread if the console cannot print. */
2275
- if (!con->write)
2276
- return;
2277
-
2278
- con->thread = kthread_run(printk_kthread_func, con,
2279
- "pr/%s%d", con->name, con->index);
2280
- if (IS_ERR(con->thread)) {
2281
- pr_err("%sconsole [%s%d]: unable to start printing thread\n",
2282
- (con->flags & CON_BOOT) ? "boot" : "",
2283
- con->name, con->index);
2284
- return;
2285
- }
2286
- pr_info("%sconsole [%s%d]: printing thread started\n",
2287
- (con->flags & CON_BOOT) ? "boot" : "",
2288
- con->name, con->index);
2289
-}
2290
-
2291
-/* protected by console_lock */
2292
-static bool kthreads_started;
2293
-
2294
-/* Must be called within console_lock(). */
2295
-static void console_try_thread(struct console *con)
2296
-{
2297
- if (kthreads_started) {
2298
- start_printk_kthread(con);
2299
- return;
2300
- }
2301
-
2302
- /*
2303
- * The printing threads have not been started yet. If this console
2304
- * can print synchronously, print all unprinted messages.
2305
- */
2306
- if (console_can_sync(con))
2307
- print_sync_until(con, prb_next_seq(prb));
2308
-}
2309
-
23102136 #else /* CONFIG_PRINTK */
23112137
2312
-#define prb_first_valid_seq(rb) 0
2313
-#define prb_next_seq(rb) 0
2138
+#define LOG_LINE_MAX 0
2139
+#define PREFIX_MAX 0
2140
+#define printk_time false
23142141
2315
-#define console_try_thread(con)
2142
+#define prb_read_valid(rb, seq, r) false
2143
+#define prb_first_valid_seq(rb) 0
2144
+
2145
+static u64 syslog_seq;
2146
+static u64 console_seq;
2147
+static u64 exclusive_console_stop_seq;
2148
+static unsigned long console_dropped;
2149
+
2150
+static size_t record_print_text(const struct printk_record *r,
2151
+ bool syslog, bool time)
2152
+{
2153
+ return 0;
2154
+}
2155
+static ssize_t info_print_ext_header(char *buf, size_t size,
2156
+ struct printk_info *info)
2157
+{
2158
+ return 0;
2159
+}
2160
+static ssize_t msg_print_ext_body(char *buf, size_t size,
2161
+ char *text, size_t text_len,
2162
+ struct dev_printk_info *dev_info) { return 0; }
2163
+static void console_lock_spinning_enable(void) { }
2164
+static int console_lock_spinning_disable_and_check(void) { return 0; }
2165
+static void call_console_drivers(const char *ext_text, size_t ext_len,
2166
+ const char *text, size_t len) {}
2167
+static bool suppress_message_printing(int level) { return false; }
23162168
23172169 #endif /* CONFIG_PRINTK */
23182170
....@@ -2563,6 +2415,34 @@
25632415 }
25642416 EXPORT_SYMBOL(is_console_locked);
25652417
2418
+/*
2419
+ * Check if we have any console that is capable of printing while cpu is
2420
+ * booting or shutting down. Requires console_sem.
2421
+ */
2422
+static int have_callable_console(void)
2423
+{
2424
+ struct console *con;
2425
+
2426
+ for_each_console(con)
2427
+ if ((con->flags & CON_ENABLED) &&
2428
+ (con->flags & CON_ANYTIME))
2429
+ return 1;
2430
+
2431
+ return 0;
2432
+}
2433
+
2434
+/*
2435
+ * Can we actually use the console at this time on this cpu?
2436
+ *
2437
+ * Console drivers may assume that per-cpu resources have been allocated. So
2438
+ * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
2439
+ * call them until this CPU is officially up.
2440
+ */
2441
+static inline int can_use_console(void)
2442
+{
2443
+ return cpu_online(raw_smp_processor_id()) || have_callable_console();
2444
+}
2445
+
25662446 /**
25672447 * console_unlock - unlock the console system
25682448 *
....@@ -2579,14 +2459,142 @@
25792459 */
25802460 void console_unlock(void)
25812461 {
2462
+ static char ext_text[CONSOLE_EXT_LOG_MAX];
2463
+ static char text[LOG_LINE_MAX + PREFIX_MAX];
2464
+ unsigned long flags;
2465
+ bool do_cond_resched, retry;
2466
+ struct printk_info info;
2467
+ struct printk_record r;
2468
+
25822469 if (console_suspended) {
25832470 up_console_sem();
25842471 return;
25852472 }
25862473
2474
+ prb_rec_init_rd(&r, &info, text, sizeof(text));
2475
+
2476
+ /*
2477
+ * Console drivers are called with interrupts disabled, so
2478
+ * @console_may_schedule should be cleared before; however, we may
2479
+ * end up dumping a lot of lines, for example, if called from
2480
+ * console registration path, and should invoke cond_resched()
2481
+ * between lines if allowable. Not doing so can cause a very long
2482
+ * scheduling stall on a slow console leading to RCU stall and
2483
+ * softlockup warnings which exacerbate the issue with more
2484
+ * messages practically incapacitating the system.
2485
+ *
2486
+ * console_trylock() is not able to detect the preemptive
2487
+ * context reliably. Therefore the value must be stored before
2488
+ * and cleared after the "again" goto label.
2489
+ */
2490
+ do_cond_resched = console_may_schedule;
2491
+again:
2492
+ console_may_schedule = 0;
2493
+
2494
+ /*
2495
+ * We released the console_sem lock, so we need to recheck if
2496
+ * cpu is online and (if not) is there at least one CON_ANYTIME
2497
+ * console.
2498
+ */
2499
+ if (!can_use_console()) {
2500
+ console_locked = 0;
2501
+ up_console_sem();
2502
+ return;
2503
+ }
2504
+
2505
+ for (;;) {
2506
+ size_t ext_len = 0;
2507
+ size_t len;
2508
+
2509
+ printk_safe_enter_irqsave(flags);
2510
+ raw_spin_lock(&logbuf_lock);
2511
+skip:
2512
+ if (!prb_read_valid(prb, console_seq, &r))
2513
+ break;
2514
+
2515
+ if (console_seq != r.info->seq) {
2516
+ console_dropped += r.info->seq - console_seq;
2517
+ console_seq = r.info->seq;
2518
+ }
2519
+
2520
+ if (suppress_message_printing(r.info->level)) {
2521
+ /*
2522
+ * Skip record we have buffered and already printed
2523
+ * directly to the console when we received it, and
2524
+ * record that has level above the console loglevel.
2525
+ */
2526
+ console_seq++;
2527
+ goto skip;
2528
+ }
2529
+
2530
+ /* Output to all consoles once old messages replayed. */
2531
+ if (unlikely(exclusive_console &&
2532
+ console_seq >= exclusive_console_stop_seq)) {
2533
+ exclusive_console = NULL;
2534
+ }
2535
+
2536
+ /*
2537
+ * Handle extended console text first because later
2538
+ * record_print_text() will modify the record buffer in-place.
2539
+ */
2540
+ if (nr_ext_console_drivers) {
2541
+ ext_len = info_print_ext_header(ext_text,
2542
+ sizeof(ext_text),
2543
+ r.info);
2544
+ ext_len += msg_print_ext_body(ext_text + ext_len,
2545
+ sizeof(ext_text) - ext_len,
2546
+ &r.text_buf[0],
2547
+ r.info->text_len,
2548
+ &r.info->dev_info);
2549
+ }
2550
+ len = record_print_text(&r,
2551
+ console_msg_format & MSG_FORMAT_SYSLOG,
2552
+ printk_time);
2553
+ console_seq++;
2554
+ raw_spin_unlock(&logbuf_lock);
2555
+
2556
+ /*
2557
+ * While actively printing out messages, if another printk()
2558
+ * were to occur on another CPU, it may wait for this one to
2559
+ * finish. This task can not be preempted if there is a
2560
+ * waiter waiting to take over.
2561
+ */
2562
+ console_lock_spinning_enable();
2563
+
2564
+ stop_critical_timings(); /* don't trace print latency */
2565
+ call_console_drivers(ext_text, ext_len, text, len);
2566
+ start_critical_timings();
2567
+
2568
+ if (console_lock_spinning_disable_and_check()) {
2569
+ printk_safe_exit_irqrestore(flags);
2570
+ return;
2571
+ }
2572
+
2573
+ printk_safe_exit_irqrestore(flags);
2574
+
2575
+ if (do_cond_resched)
2576
+ cond_resched();
2577
+ }
2578
+
25872579 console_locked = 0;
25882580
2581
+ raw_spin_unlock(&logbuf_lock);
2582
+
25892583 up_console_sem();
2584
+
2585
+ /*
2586
+ * Someone could have filled up the buffer again, so re-check if there's
2587
+ * something to flush. In case we cannot trylock the console_sem again,
2588
+ * there's a new owner and the console_unlock() from them will do the
2589
+ * flush, no worries.
2590
+ */
2591
+ raw_spin_lock(&logbuf_lock);
2592
+ retry = prb_read_valid(prb, console_seq, NULL);
2593
+ raw_spin_unlock(&logbuf_lock);
2594
+ printk_safe_exit_irqrestore(flags);
2595
+
2596
+ if (retry && console_trylock())
2597
+ goto again;
25902598 }
25912599 EXPORT_SYMBOL(console_unlock);
25922600
....@@ -2636,20 +2644,23 @@
26362644 */
26372645 void console_flush_on_panic(enum con_flush_mode mode)
26382646 {
2639
- struct console *c;
2640
- u64 seq;
2641
-
2642
- if (!console_trylock())
2643
- return;
2644
-
2647
+ /*
2648
+ * If someone else is holding the console lock, trylock will fail
2649
+ * and may_schedule may be set. Ignore and proceed to unlock so
2650
+ * that messages are flushed out. As this can be called from any
2651
+ * context and we don't want to get preempted while flushing,
2652
+ * ensure may_schedule is cleared.
2653
+ */
2654
+ console_trylock();
26452655 console_may_schedule = 0;
26462656
26472657 if (mode == CONSOLE_REPLAY_ALL) {
2648
- seq = prb_first_valid_seq(prb);
2649
- for_each_console(c)
2650
- atomic64_set(&c->printk_seq, seq);
2651
- }
2658
+ unsigned long flags;
26522659
2660
+ logbuf_lock_irqsave(flags);
2661
+ console_seq = prb_first_valid_seq(prb);
2662
+ logbuf_unlock_irqrestore(flags);
2663
+ }
26532664 console_unlock();
26542665 }
26552666
....@@ -2784,6 +2795,7 @@
27842795 */
27852796 void register_console(struct console *newcon)
27862797 {
2798
+ unsigned long flags;
27872799 struct console *bcon = NULL;
27882800 int err;
27892801
....@@ -2806,8 +2818,6 @@
28062818 }
28072819 }
28082820 }
2809
-
2810
- newcon->thread = NULL;
28112821
28122822 if (console_drivers && console_drivers->flags & CON_BOOT)
28132823 bcon = console_drivers;
....@@ -2850,10 +2860,8 @@
28502860 * the real console are the same physical device, it's annoying to
28512861 * see the beginning boot messages twice
28522862 */
2853
- if (bcon && ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV)) {
2863
+ if (bcon && ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV))
28542864 newcon->flags &= ~CON_PRINTBUFFER;
2855
- newcon->flags |= CON_HANDOVER;
2856
- }
28572865
28582866 /*
28592867 * Put this console in the list - keep the
....@@ -2875,12 +2883,26 @@
28752883 if (newcon->flags & CON_EXTENDED)
28762884 nr_ext_console_drivers++;
28772885
2878
- if (newcon->flags & CON_PRINTBUFFER)
2879
- atomic64_set(&newcon->printk_seq, 0);
2880
- else
2881
- atomic64_set(&newcon->printk_seq, prb_next_seq(prb));
2882
-
2883
- console_try_thread(newcon);
2886
+ if (newcon->flags & CON_PRINTBUFFER) {
2887
+ /*
2888
+ * console_unlock(); will print out the buffered messages
2889
+ * for us.
2890
+ */
2891
+ logbuf_lock_irqsave(flags);
2892
+ /*
2893
+ * We're about to replay the log buffer. Only do this to the
2894
+ * just-registered console to avoid excessive message spam to
2895
+ * the already-registered consoles.
2896
+ *
2897
+ * Set exclusive_console with disabled interrupts to reduce
2898
+ * race window with eventual console_flush_on_panic() that
2899
+ * ignores console_lock.
2900
+ */
2901
+ exclusive_console = newcon;
2902
+ exclusive_console_stop_seq = console_seq;
2903
+ console_seq = syslog_seq;
2904
+ logbuf_unlock_irqrestore(flags);
2905
+ }
28842906 console_unlock();
28852907 console_sysfs_notify();
28862908
....@@ -2953,9 +2975,6 @@
29532975 console->flags &= ~CON_ENABLED;
29542976 console_unlock();
29552977 console_sysfs_notify();
2956
-
2957
- if (console->thread && !IS_ERR(console->thread))
2958
- kthread_stop(console->thread);
29592978
29602979 if (console->exit)
29612980 res = console->exit(console);
....@@ -3039,15 +3058,6 @@
30393058 unregister_console(con);
30403059 }
30413060 }
3042
-
3043
-#ifdef CONFIG_PRINTK
3044
- console_lock();
3045
- for_each_console(con)
3046
- start_printk_kthread(con);
3047
- kthreads_started = true;
3048
- console_unlock();
3049
-#endif
3050
-
30513061 ret = cpuhp_setup_state_nocalls(CPUHP_PRINTK_DEAD, "printk:dead", NULL,
30523062 console_cpu_notify);
30533063 WARN_ON(ret < 0);
....@@ -3063,6 +3073,7 @@
30633073 * Delayed printk version, for scheduler-internal messages:
30643074 */
30653075 #define PRINTK_PENDING_WAKEUP 0x01
3076
+#define PRINTK_PENDING_OUTPUT 0x02
30663077
30673078 static DEFINE_PER_CPU(int, printk_pending);
30683079
....@@ -3070,8 +3081,14 @@
30703081 {
30713082 int pending = __this_cpu_xchg(printk_pending, 0);
30723083
3084
+ if (pending & PRINTK_PENDING_OUTPUT) {
3085
+ /* If trylock fails, someone else is doing the printing */
3086
+ if (console_trylock())
3087
+ console_unlock();
3088
+ }
3089
+
30733090 if (pending & PRINTK_PENDING_WAKEUP)
3074
- wake_up_interruptible_all(&log_wait);
3091
+ wake_up_interruptible(&log_wait);
30753092 }
30763093
30773094 static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
....@@ -3092,10 +3109,25 @@
30923109 preempt_enable();
30933110 }
30943111
3095
-__printf(1, 0)
3096
-static int vprintk_deferred(const char *fmt, va_list args)
3112
+void defer_console_output(void)
30973113 {
3098
- return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
3114
+ if (!printk_percpu_data_ready())
3115
+ return;
3116
+
3117
+ preempt_disable();
3118
+ __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
3119
+ irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
3120
+ preempt_enable();
3121
+}
3122
+
3123
+int vprintk_deferred(const char *fmt, va_list args)
3124
+{
3125
+ int r;
3126
+
3127
+ r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, fmt, args);
3128
+ defer_console_output();
3129
+
3130
+ return r;
30993131 }
31003132
31013133 int printk_deferred(const char *fmt, ...)
....@@ -3235,26 +3267,8 @@
32353267 */
32363268 void kmsg_dump(enum kmsg_dump_reason reason)
32373269 {
3238
- struct kmsg_dumper_iter iter;
32393270 struct kmsg_dumper *dumper;
3240
-
3241
- if (!oops_in_progress) {
3242
- /*
3243
- * If atomic consoles are available, activate kernel sync mode
3244
- * to make sure any final messages are visible. The trailing
3245
- * printk message is important to flush any pending messages.
3246
- */
3247
- if (have_atomic_console()) {
3248
- sync_mode = true;
3249
- pr_info("enabled sync mode\n");
3250
- }
3251
-
3252
- /*
3253
- * Give the printing threads time to flush, allowing up to
3254
- * 1s of no printing forward progress before giving up.
3255
- */
3256
- pr_flush(1000, true);
3257
- }
3271
+ unsigned long flags;
32583272
32593273 rcu_read_lock();
32603274 list_for_each_entry_rcu(dumper, &dump_list, list) {
....@@ -3272,18 +3286,81 @@
32723286 continue;
32733287
32743288 /* initialize iterator with data about the stored records */
3275
- iter.active = true;
3276
- kmsg_dump_rewind(&iter);
3289
+ dumper->active = true;
3290
+
3291
+ logbuf_lock_irqsave(flags);
3292
+ dumper->cur_seq = clear_seq;
3293
+ dumper->next_seq = prb_next_seq(prb);
3294
+ logbuf_unlock_irqrestore(flags);
32773295
32783296 /* invoke dumper which will iterate over records */
3279
- dumper->dump(dumper, reason, &iter);
3297
+ dumper->dump(dumper, reason);
3298
+
3299
+ /* reset iterator */
3300
+ dumper->active = false;
32803301 }
32813302 rcu_read_unlock();
32823303 }
32833304
32843305 /**
3306
+ * kmsg_dump_get_line_nolock - retrieve one kmsg log line (unlocked version)
3307
+ * @dumper: registered kmsg dumper
3308
+ * @syslog: include the "<4>" prefixes
3309
+ * @line: buffer to copy the line to
3310
+ * @size: maximum size of the buffer
3311
+ * @len: length of line placed into buffer
3312
+ *
3313
+ * Start at the beginning of the kmsg buffer, with the oldest kmsg
3314
+ * record, and copy one record into the provided buffer.
3315
+ *
3316
+ * Consecutive calls will return the next available record moving
3317
+ * towards the end of the buffer with the youngest messages.
3318
+ *
3319
+ * A return value of FALSE indicates that there are no more records to
3320
+ * read.
3321
+ *
3322
+ * The function is similar to kmsg_dump_get_line(), but grabs no locks.
3323
+ */
3324
+bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
3325
+ char *line, size_t size, size_t *len)
3326
+{
3327
+ struct printk_info info;
3328
+ unsigned int line_count;
3329
+ struct printk_record r;
3330
+ size_t l = 0;
3331
+ bool ret = false;
3332
+
3333
+ prb_rec_init_rd(&r, &info, line, size);
3334
+
3335
+ if (!dumper->active)
3336
+ goto out;
3337
+
3338
+ /* Read text or count text lines? */
3339
+ if (line) {
3340
+ if (!prb_read_valid(prb, dumper->cur_seq, &r))
3341
+ goto out;
3342
+ l = record_print_text(&r, syslog, printk_time);
3343
+ } else {
3344
+ if (!prb_read_valid_info(prb, dumper->cur_seq,
3345
+ &info, &line_count)) {
3346
+ goto out;
3347
+ }
3348
+ l = get_record_print_text_size(&info, line_count, syslog,
3349
+ printk_time);
3350
+
3351
+ }
3352
+
3353
+ dumper->cur_seq = r.info->seq + 1;
3354
+ ret = true;
3355
+out:
3356
+ if (len)
3357
+ *len = l;
3358
+ return ret;
3359
+}
3360
+
3361
+/**
32853362 * kmsg_dump_get_line - retrieve one kmsg log line
3286
- * @iter: kmsg dumper iterator
3363
+ * @dumper: registered kmsg dumper
32873364 * @syslog: include the "<4>" prefixes
32883365 * @line: buffer to copy the line to
32893366 * @size: maximum size of the buffer
....@@ -3298,47 +3375,23 @@
32983375 * A return value of FALSE indicates that there are no more records to
32993376 * read.
33003377 */
3301
-bool kmsg_dump_get_line(struct kmsg_dumper_iter *iter, bool syslog,
3378
+bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
33023379 char *line, size_t size, size_t *len)
33033380 {
3304
- struct printk_info info;
3305
- unsigned int line_count;
3306
- struct printk_record r;
3307
- size_t l = 0;
3308
- bool ret = false;
3381
+ unsigned long flags;
3382
+ bool ret;
33093383
3310
- prb_rec_init_rd(&r, &info, line, size);
3384
+ logbuf_lock_irqsave(flags);
3385
+ ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
3386
+ logbuf_unlock_irqrestore(flags);
33113387
3312
- if (!iter->active)
3313
- goto out;
3314
-
3315
- /* Read text or count text lines? */
3316
- if (line) {
3317
- if (!prb_read_valid(prb, iter->cur_seq, &r))
3318
- goto out;
3319
- l = record_print_text(&r, syslog, printk_time);
3320
- } else {
3321
- if (!prb_read_valid_info(prb, iter->cur_seq,
3322
- &info, &line_count)) {
3323
- goto out;
3324
- }
3325
- l = get_record_print_text_size(&info, line_count, syslog,
3326
- printk_time);
3327
-
3328
- }
3329
-
3330
- iter->cur_seq = r.info->seq + 1;
3331
- ret = true;
3332
-out:
3333
- if (len)
3334
- *len = l;
33353388 return ret;
33363389 }
33373390 EXPORT_SYMBOL_GPL(kmsg_dump_get_line);
33383391
33393392 /**
33403393 * kmsg_dump_get_buffer - copy kmsg log lines
3341
- * @iter: kmsg dumper iterator
3394
+ * @dumper: registered kmsg dumper
33423395 * @syslog: include the "<4>" prefixes
33433396 * @buf: buffer to copy the line to
33443397 * @size: maximum size of the buffer
....@@ -3355,258 +3408,116 @@
33553408 * A return value of FALSE indicates that there are no more records to
33563409 * read.
33573410 */
3358
-bool kmsg_dump_get_buffer(struct kmsg_dumper_iter *iter, bool syslog,
3359
- char *buf, size_t size, size_t *len_out)
3411
+bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
3412
+ char *buf, size_t size, size_t *len)
33603413 {
33613414 struct printk_info info;
3415
+ unsigned int line_count;
33623416 struct printk_record r;
3417
+ unsigned long flags;
33633418 u64 seq;
33643419 u64 next_seq;
3365
- size_t len = 0;
3420
+ size_t l = 0;
33663421 bool ret = false;
33673422 bool time = printk_time;
33683423
3369
- if (!iter->active || !buf || !size)
3424
+ prb_rec_init_rd(&r, &info, buf, size);
3425
+
3426
+ if (!dumper->active || !buf || !size)
33703427 goto out;
33713428
3372
- if (prb_read_valid_info(prb, iter->cur_seq, &info, NULL)) {
3373
- if (info.seq != iter->cur_seq) {
3429
+ logbuf_lock_irqsave(flags);
3430
+ if (prb_read_valid_info(prb, dumper->cur_seq, &info, NULL)) {
3431
+ if (info.seq != dumper->cur_seq) {
33743432 /* messages are gone, move to first available one */
3375
- iter->cur_seq = info.seq;
3433
+ dumper->cur_seq = info.seq;
33763434 }
33773435 }
33783436
33793437 /* last entry */
3380
- if (iter->cur_seq >= iter->next_seq)
3438
+ if (dumper->cur_seq >= dumper->next_seq) {
3439
+ logbuf_unlock_irqrestore(flags);
33813440 goto out;
3382
-
3383
- /*
3384
- * Find first record that fits, including all following records,
3385
- * into the user-provided buffer for this dump. Pass in size-1
3386
- * because this function (by way of record_print_text()) will
3387
- * not write more than size-1 bytes of text into @buf.
3388
- */
3389
- seq = find_first_fitting_seq(iter->cur_seq, iter->next_seq,
3390
- size - 1, syslog, time);
3391
-
3392
- /*
3393
- * Next kmsg_dump_get_buffer() invocation will dump block of
3394
- * older records stored right before this one.
3395
- */
3396
- next_seq = seq;
3397
-
3398
- prb_rec_init_rd(&r, &info, buf, size);
3399
-
3400
- len = 0;
3401
- prb_for_each_record(seq, prb, seq, &r) {
3402
- if (r.info->seq >= iter->next_seq)
3403
- break;
3404
-
3405
- len += record_print_text(&r, syslog, time);
3406
-
3407
- /* Adjust record to store to remaining buffer space. */
3408
- prb_rec_init_rd(&r, &info, buf + len, size - len);
34093441 }
34103442
3411
- iter->next_seq = next_seq;
3443
+ /* calculate length of entire buffer */
3444
+ seq = dumper->cur_seq;
3445
+ while (prb_read_valid_info(prb, seq, &info, &line_count)) {
3446
+ if (r.info->seq >= dumper->next_seq)
3447
+ break;
3448
+ l += get_record_print_text_size(&info, line_count, syslog, time);
3449
+ seq = r.info->seq + 1;
3450
+ }
3451
+
3452
+ /* move first record forward until length fits into the buffer */
3453
+ seq = dumper->cur_seq;
3454
+ while (l >= size && prb_read_valid_info(prb, seq,
3455
+ &info, &line_count)) {
3456
+ if (r.info->seq >= dumper->next_seq)
3457
+ break;
3458
+ l -= get_record_print_text_size(&info, line_count, syslog, time);
3459
+ seq = r.info->seq + 1;
3460
+ }
3461
+
3462
+ /* last message in next interation */
3463
+ next_seq = seq;
3464
+
3465
+ /* actually read text into the buffer now */
3466
+ l = 0;
3467
+ while (prb_read_valid(prb, seq, &r)) {
3468
+ if (r.info->seq >= dumper->next_seq)
3469
+ break;
3470
+
3471
+ l += record_print_text(&r, syslog, time);
3472
+
3473
+ /* adjust record to store to remaining buffer space */
3474
+ prb_rec_init_rd(&r, &info, buf + l, size - l);
3475
+
3476
+ seq = r.info->seq + 1;
3477
+ }
3478
+
3479
+ dumper->next_seq = next_seq;
34123480 ret = true;
3481
+ logbuf_unlock_irqrestore(flags);
34133482 out:
3414
- if (len_out)
3415
- *len_out = len;
3483
+ if (len)
3484
+ *len = l;
34163485 return ret;
34173486 }
34183487 EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
34193488
34203489 /**
3490
+ * kmsg_dump_rewind_nolock - reset the iterator (unlocked version)
3491
+ * @dumper: registered kmsg dumper
3492
+ *
3493
+ * Reset the dumper's iterator so that kmsg_dump_get_line() and
3494
+ * kmsg_dump_get_buffer() can be called again and used multiple
3495
+ * times within the same dumper.dump() callback.
3496
+ *
3497
+ * The function is similar to kmsg_dump_rewind(), but grabs no locks.
3498
+ */
3499
+void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
3500
+{
3501
+ dumper->cur_seq = clear_seq;
3502
+ dumper->next_seq = prb_next_seq(prb);
3503
+}
3504
+
3505
+/**
34213506 * kmsg_dump_rewind - reset the iterator
3422
- * @iter: kmsg dumper iterator
3507
+ * @dumper: registered kmsg dumper
34233508 *
34243509 * Reset the dumper's iterator so that kmsg_dump_get_line() and
34253510 * kmsg_dump_get_buffer() can be called again and used multiple
34263511 * times within the same dumper.dump() callback.
34273512 */
3428
-void kmsg_dump_rewind(struct kmsg_dumper_iter *iter)
3513
+void kmsg_dump_rewind(struct kmsg_dumper *dumper)
34293514 {
3430
- iter->cur_seq = latched_seq_read_nolock(&clear_seq);
3431
- iter->next_seq = prb_next_seq(prb);
3515
+ unsigned long flags;
3516
+
3517
+ logbuf_lock_irqsave(flags);
3518
+ kmsg_dump_rewind_nolock(dumper);
3519
+ logbuf_unlock_irqrestore(flags);
34323520 }
34333521 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
34343522
34353523 #endif
3436
-
3437
-struct prb_cpulock {
3438
- atomic_t owner;
3439
- unsigned long __percpu *irqflags;
3440
-};
3441
-
3442
-#define DECLARE_STATIC_PRINTKRB_CPULOCK(name) \
3443
-static DEFINE_PER_CPU(unsigned long, _##name##_percpu_irqflags); \
3444
-static struct prb_cpulock name = { \
3445
- .owner = ATOMIC_INIT(-1), \
3446
- .irqflags = &_##name##_percpu_irqflags, \
3447
-}
3448
-
3449
-static bool __prb_trylock(struct prb_cpulock *cpu_lock,
3450
- unsigned int *cpu_store)
3451
-{
3452
- unsigned long *flags;
3453
- unsigned int cpu;
3454
-
3455
- cpu = get_cpu();
3456
-
3457
- *cpu_store = atomic_read(&cpu_lock->owner);
3458
- /* memory barrier to ensure the current lock owner is visible */
3459
- smp_rmb();
3460
- if (*cpu_store == -1) {
3461
- flags = per_cpu_ptr(cpu_lock->irqflags, cpu);
3462
- local_irq_save(*flags);
3463
- if (atomic_try_cmpxchg_acquire(&cpu_lock->owner,
3464
- cpu_store, cpu)) {
3465
- return true;
3466
- }
3467
- local_irq_restore(*flags);
3468
- } else if (*cpu_store == cpu) {
3469
- return true;
3470
- }
3471
-
3472
- put_cpu();
3473
- return false;
3474
-}
3475
-
3476
-/*
3477
- * prb_lock: Perform a processor-reentrant spin lock.
3478
- * @cpu_lock: A pointer to the lock object.
3479
- * @cpu_store: A "flags" pointer to store lock status information.
3480
- *
3481
- * If no processor has the lock, the calling processor takes the lock and
3482
- * becomes the owner. If the calling processor is already the owner of the
3483
- * lock, this function succeeds immediately. If lock is locked by another
3484
- * processor, this function spins until the calling processor becomes the
3485
- * owner.
3486
- *
3487
- * It is safe to call this function from any context and state.
3488
- */
3489
-static void prb_lock(struct prb_cpulock *cpu_lock, unsigned int *cpu_store)
3490
-{
3491
- for (;;) {
3492
- if (__prb_trylock(cpu_lock, cpu_store))
3493
- break;
3494
- cpu_relax();
3495
- }
3496
-}
3497
-
3498
-/*
3499
- * prb_unlock: Perform a processor-reentrant spin unlock.
3500
- * @cpu_lock: A pointer to the lock object.
3501
- * @cpu_store: A "flags" object storing lock status information.
3502
- *
3503
- * Release the lock. The calling processor must be the owner of the lock.
3504
- *
3505
- * It is safe to call this function from any context and state.
3506
- */
3507
-static void prb_unlock(struct prb_cpulock *cpu_lock, unsigned int cpu_store)
3508
-{
3509
- unsigned long *flags;
3510
- unsigned int cpu;
3511
-
3512
- cpu = atomic_read(&cpu_lock->owner);
3513
- atomic_set_release(&cpu_lock->owner, cpu_store);
3514
-
3515
- if (cpu_store == -1) {
3516
- flags = per_cpu_ptr(cpu_lock->irqflags, cpu);
3517
- local_irq_restore(*flags);
3518
- }
3519
-
3520
- put_cpu();
3521
-}
3522
-
3523
-DECLARE_STATIC_PRINTKRB_CPULOCK(printk_cpulock);
3524
-
3525
-void console_atomic_lock(unsigned int *flags)
3526
-{
3527
- prb_lock(&printk_cpulock, flags);
3528
-}
3529
-EXPORT_SYMBOL(console_atomic_lock);
3530
-
3531
-void console_atomic_unlock(unsigned int flags)
3532
-{
3533
- prb_unlock(&printk_cpulock, flags);
3534
-}
3535
-EXPORT_SYMBOL(console_atomic_unlock);
3536
-
3537
-static void pr_msleep(bool may_sleep, int ms)
3538
-{
3539
- if (may_sleep) {
3540
- msleep(ms);
3541
- } else {
3542
- while (ms--)
3543
- udelay(1000);
3544
- }
3545
-}
3546
-
3547
-/**
3548
- * pr_flush() - Wait for printing threads to catch up.
3549
- *
3550
- * @timeout_ms: The maximum time (in ms) to wait.
3551
- * @reset_on_progress: Reset the timeout if forward progress is seen.
3552
- *
3553
- * A value of 0 for @timeout_ms means no waiting will occur. A value of -1
3554
- * represents infinite waiting.
3555
- *
3556
- * If @reset_on_progress is true, the timeout will be reset whenever any
3557
- * printer has been seen to make some forward progress.
3558
- *
3559
- * Context: Any context.
3560
- * Return: true if all enabled printers are caught up.
3561
- */
3562
-bool pr_flush(int timeout_ms, bool reset_on_progress)
3563
-{
3564
- int remaining = timeout_ms;
3565
- struct console *con;
3566
- u64 last_diff = 0;
3567
- bool may_sleep;
3568
- u64 printk_seq;
3569
- u64 diff;
3570
- u64 seq;
3571
-
3572
- may_sleep = (preemptible() &&
3573
- !in_softirq() &&
3574
- system_state >= SYSTEM_RUNNING);
3575
-
3576
- seq = prb_next_seq(prb);
3577
-
3578
- for (;;) {
3579
- diff = 0;
3580
-
3581
- for_each_console(con) {
3582
- if (!(con->flags & CON_ENABLED))
3583
- continue;
3584
- if (!con->write && !con->write_atomic)
3585
- continue;
3586
- printk_seq = atomic64_read(&con->printk_seq);
3587
- if (printk_seq < seq)
3588
- diff += seq - printk_seq;
3589
- }
3590
-
3591
- if (diff != last_diff && reset_on_progress)
3592
- remaining = timeout_ms;
3593
-
3594
- if (!diff || remaining == 0)
3595
- break;
3596
-
3597
- if (remaining < 0) {
3598
- pr_msleep(may_sleep, 100);
3599
- } else if (remaining < 100) {
3600
- pr_msleep(may_sleep, remaining);
3601
- remaining = 0;
3602
- } else {
3603
- pr_msleep(may_sleep, 100);
3604
- remaining -= 100;
3605
- }
3606
-
3607
- last_diff = diff;
3608
- }
3609
-
3610
- return (diff == 0);
3611
-}
3612
-EXPORT_SYMBOL(pr_flush);