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.

Reply via email to