Messages in this thread Patch in this message | | | Subject | Re: [PATCH] printk: Add caller information to printk() output. | From | Tetsuo Handa <> | Date | Fri, 07 Dec 2018 13:58:29 +0900 |
| |
Sergey Senozhatsky wrote: > Do we need PIDs at all?
Yes. I don't like truncating caller information, for I think that PID is used for not only reconstructing messages but also serving as a clue for understanding what the process was doing.
> PIDs don't tell that much. When you are grepping serial log you can't > actually tell if PID 15000 there and PID 15000 here, 200000 log lines > apart, are same processes; or did PIDs wrap around? And you probably > don't even care.
I don't care whether PIDs wrapped around. If the goal were to check whether PIDs wrapped around, we would print "struct task_struct"->[real_]start_time together.
> All you need is a way to reconstruct a message around > some very specific place in the log - say in a range [-500, +500] lines, > assuming that a backtrace you are trying to reconstruct is badly fragmented. > I think, even 3 lower digits of a PID should do the trick.
3 lower digits is insufficient for reconstructing PID of interest; it can conflict at 1/1000 probability. 3 lower hexadecimal digits might be better but is insufficient; it can still conflict at 1/4096.
3 lower base64 characters might be sufficient; it conflicts at only 1/262144. 4 base64 characters is sufficient, for 64*64*64*64 > PID_MAX_LIMIT. But what do you feel from example output shown below? While no truncation of caller information, it is hard for humans to understand.
---------------------------------------- @@ -1227,39 +1254,47 @@ static inline void boot_delay_msec(int level) static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME); module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); -static size_t print_time(u64 ts, char *buf) -{ - unsigned long rem_nsec = do_div(ts, 1000000000); - - if (!buf) - return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts); - - return sprintf(buf, "[%5lu.%06lu] ", - (unsigned long)ts, rem_nsec / 1000); -} - static size_t print_prefix(const struct printk_log *msg, bool syslog, bool time, char *buf) { size_t len = 0; - unsigned int prefix = (msg->facility << 3) | msg->level; + char tmp[PREFIX_MAX]; + if (!buf) + buf = tmp; if (syslog) { - if (buf) { - len += sprintf(buf, "<%u>", prefix); - } else { - len += 3; - if (prefix > 999) - len += 3; - else if (prefix > 99) - len += 2; - else if (prefix > 9) - len++; - } + unsigned int prefix = (msg->facility << 3) | msg->level; + + len += sprintf(buf, "<%u>", prefix); } +#ifdef CONFIG_PRINTK_FROM + buf[len++] = '['; + if (time) { + u64 ts = msg->ts_nsec; + unsigned long rem_nsec = do_div(ts, 1000000000); - if (time) - len += print_time(msg->ts_nsec, buf ? buf + len : NULL); + len += sprintf(buf + len, "%lu.%06lu", (unsigned long)ts, + rem_nsec / 1000); + } + { + static const char base64[64] = "ABCDEFGHIJKLMNOPQRSTUVWXYZ" + "abcdefghijklmnopqrstuvwxyz0123456789+/"; + u32 id = msg->from_id; + + len += sprintf(buf + len, "%c%c%c%c%c] ", + (id & 0x80000000 ? 'C' : 'T'), + base64[(id >> 18) & 63], base64[(id >> 12) & 63], + base64[(id >> 6) & 63], base64[id & 63]); + } +#else + if (time) { + u64 ts = msg->ts_nsec; + unsigned long rem_nsec = do_div(ts, 1000000000); + + len += sprintf(buf + len, "[%5lu.%06lu] ", (unsigned long)ts, + rem_nsec / 1000); + } +#endif return len; } ---------------------------------------- ---------------------------------------- [0.000000TAAAA] Disabled fast string operations [1.023286TAAAB] Performance Events: Skylake events, core PMU driver. [5.624742TAACc] systemd-fstab-g (156) used greatest stack depth: 13656 bytes left [5.680184TAAA+] input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input3 [5.681783TAACb] dracut-rootfs-g (155) used greatest stack depth: 13640 bytes left [9.299727TAAu+] ata8: SATA link down (SStatus 0 SControl 300) [15.922239TABI/] e1000: ens32 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None [15.923927TABYb] IPv6: ADDRCONF(NETDEV_UP): ens32: link is not ready [15.930537TABI/] IPv6: ADDRCONF(NETDEV_CHANGE): ens32: link becomes ready [40.506011CAAAA] random: crng init done [926.716687TAAAB] reboot: Power down ---------------------------------------- After all, printing all digits without truncation will be the better.
| |