linux打印中时间信息

使能 CONFIG_PRINTK_TIME之后，内核每行打印前面有时间信息，本文探讨一下相关代码以及时间信息的含义。

  | CONFIG_PRINTK_TIME:
  |
  | Selecting this option causes timing information to be
  | included in printk output.  This allows you to measure
  | the interval between kernel operations, including bootup
  | operations.  This is useful for identifying long delays
  | in kernel startup.
  |
  | Symbol: PRINTK_TIME [=y]
  | Prompt: Show timing information on printks
  |   Defined at lib/Kconfig.debug:2
  |   Depends on: PRINTK [=y]
  |   Location:
  |     -> Kernel hacking

 

在kernel/printk.c中：
#if defined(CONFIG_PRINTK_TIME)
static int printk_time = 1;
#else
static int printk_time = 0;
#endif
module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

   if (printk_time) {
    /* Follow the token with the time */
    char tbuf[50], *tp;
    unsigned tlen;
    unsigned long long t;
    unsigned long nanosec_rem;

    t = cpu_clock(printk_cpu);
    nanosec_rem = do_div(t, 1000000000);
    tlen = sprintf(tbuf, "[%5lu.%06lu] ",
      (unsigned long) t,
      nanosec_rem / 1000);
可以看到打印时间“.”号之前是s，之后是us。

其中的cpu_clock可参考下面代码（kernel/sched_clock.c），
void sched_clock_init(void)
{
 sched_clock_running = 1;
}

u64 sched_clock_cpu(int cpu)
{
 if (unlikely(!sched_clock_running))
  return 0;

 return sched_clock();
}

unsigned long long cpu_clock(int cpu)
{
 return sched_clock_cpu(cpu);
}

其中的sched_clock定义也在在kernel/sched_clock.c中
/*
 * Scheduler clock - returns current time in nanosec units.
 * This is default implementation.
 * Architectures and sub-architectures can override this.
 */
unsigned long long __attribute__((weak)) sched_clock(void)
{
 return (unsigned long long)(jiffies - INITIAL_JIFFIES)
     * (NSEC_PER_SEC / HZ);
}
EXPORT_SYMBOL_GPL(sched_clock);
这里的时间精度是jiffies，并非很高精度。

但在一些地方override了该weak函数，例如在arch/mips/kernel/csrc-r4k.c中有：

/*
 * Override the global weak sched_clock symbol(defined in sched_clock.c)
 * with this local implementation which uses the clocksource to get some
 * better resolution when scheduling the kernel. We accept that this wraps
 *  around for now, since it is just a relative time stamp.
 */
unsigned long long notrace sched_clock(void)
{
 return clocksource_cyc2ns(clocksource_mips.read(&clocksource_mips),
      clocksource_mips.mult, clocksource_mips.shift);
}
这个精度就上去了。

另外宏do_div的定义见inclue/asm-generic/div64.h
#if BITS_PER_LONG == 64

# define do_div(n,base) ({     \
 uint32_t __base = (base);    \
 uint32_t __rem;      \
 __rem = ((uint64_t)(n)) % __base;   \
 (n) = ((uint64_t)(n)) / __base;    \
 __rem;       \
 })

#elif BITS_PER_LONG == 32

extern uint32_t __div64_32(uint64_t *dividend, uint32_t divisor);

/* The unnecessary pointer compare is there
 * to check for type safety (n must be 64bit)
 */
# define do_div(n,base) ({    \
 uint32_t __base = (base);   \
 uint32_t __rem;     \
 (void)(((typeof((n)) *)0) == ((uint64_t *)0)); \
 if (likely(((n) >> 32) == 0)) {   \
  __rem = (uint32_t)(n) % __base;  \
  (n) = (uint32_t)(n) / __base;  \
 } else       \
  __rem = __div64_32(&(n), __base); \
 __rem;      \
 })

#else /* BITS_PER_LONG == ?? */

# error do_div() does not yet support the C64

#endif /* BITS_PER_LONG */