[Crash-utility] What is the unit for 'last_arrival' in 'task_struct.sched_info.last_arrival'.

[Dave Anderson]

----- Original Message -----
> Hi,
> 
> What is the unit for 'last_arrival' in 'task_struct.sched_info.last_arrival'
> ?
> I see that this value is used by 'ps -l' crash-utility command.
> 
> >> 
> -l display the task last_run or timestamp value, whichever applies,
> of selected, or all, tasks; the list is sorted with the most
> recently-run task (largest last_run/timestamp) shown first.
> >> 
> 
> I see that this value (16 decimal digits) is much higher than jiffies value
> (10 decimal digits) in my crash dumps.
> This value (unsigned long long) seems to be equal to the 'jiffies' (unsigned
> long) value when the task was scheduled.
> 
> crash> p jiffies
> jiffies = $9 = 5310085968
> crash>
> 
> crash> ps -l
> ..
> [4058835599089874] PID: 4136 TASK: ffff8801309ce640 CPU: 4 COMMAND: "kcapwdt"
> ...
> 
> System info:
> -----------------
> MACHINE: x86_64 (2533 Mhz)
> Linux Kernel Version : 3.2.30
> 
> Thanks,
> Saravanan

They are different entities.  The jiffies value is the number of ticks
that have occurred since the system booted, incremented by one during
each timer interrupt, which occur "HZ" times per second.  On an x86_64
with a CONFIG_HZ of 1000, you can see it incrementing on a live system:
  
  crash> repeat -1 p jiffies
  jiffies = $4 = 4890813048
  jiffies = $5 = 4890814058
  jiffies = $6 = 4890815067
  jiffies = $7 = 4890816077
  jiffies = $8 = 4890817087
  jiffies = $9 = 4890818097
  jiffies = $10 = 4890819107
  
The task_struct.sched_info.last_arrival value is a 64-bit timestamp value
that is taken from the task's per-cpu runqueue.clock.  It gets set in the
kernel here:

  static void sched_info_arrive(struct rq *rq, struct task_struct *t)
  {
          unsigned long long now = rq_clock(rq), delta = 0;
  
          if (t->sched_info.last_queued)
                  delta = now - t->sched_info.last_queued;
          sched_info_reset_dequeued(t);
          t->sched_info.run_delay += delta;
          t->sched_info.last_arrival = now;
          t->sched_info.pcount++;
  
          rq_sched_info_arrive(rq, delta);
  }

The per-cpu rq->clock 64-bit nanosecond-based timestamp can be watched
on a live system for a particular cpu.  For example:
  
  crash> runq
  CPU 0 RUNQUEUE: ffff88021e214040
    CURRENT: PID: 0      TASK: ffffffff81c13440  COMMAND: "swapper/0"
    RT PRIO_ARRAY: ffff88021e2141c0
       [no tasks queued]
    CFS RB_ROOT: ffff88021e2140d8
       [no tasks queued]
  
  ...
  
Taking cpu 0's rq address of ffff88021e214040 above, you can get
a rough approximation showing that its clock advances 1000000000 
times a second:
  
  crash> repeat -1 rq.clock ffff88021e214040
    clock = 596217293435441
    clock = 596218400742837
    clock = 596219506034449
    clock = 596220606332511
    clock = 596221706630214
    clock = 596222807928565
    clock = 596223913227970
    clock = 596225016526769
    clock = 596226128827938
    clock = 596227241129325
    clock = 596228351913056
  ...
  
Dave