idlestat seg fault when reading a report file

[Daniel Lezcano]

version = 6
cpus=5
       trace-cmd-4347 [001] 5231.042936: sched_process_exit: comm=trace-cmd pid=4347 prio=120
       trace-cmd-4347 [001] 5231.042987: sched_stat_runtime: comm=trace-cmd pid=4347 runtime=6912583 [ns] vruntime=791546941888 [ns]
       trace-cmd-4347 [001] 5231.042992: sched_load_se: pid 4347 : period=47970 sum=7292 contrib=23 run=1
       trace-cmd-4347 [001] 5231.042995: sched_load_contrib: cpu: 1 runnable=155 blocked=0
       trace-cmd-4347 [001] 5231.042996: sched_load_contrib: cpu: 1 runnable=0 blocked=0
       trace-cmd-4347 [001] 5231.043000: sched_load_rq: cpu: 1 period=46353 sum=7245 decay=1
       trace-cmd-4347 [001] 5231.043004: sched_stat_runtime: comm=trace-cmd pid=4347 runtime=18875 [ns] vruntime=791546960763 [ns]
       trace-cmd-4347 [001] 5231.043005: sched_load_contrib: cpu: 1 runnable=155 blocked=0
       trace-cmd-4347 [001] 5231.043007: sched_load_rq: cpu: 1 period=46371 sum=7245 decay=0
       trace-cmd-4347 [001] 5231.043014: irq_handler_entry: irq=27 name=arch_timer
       trace-cmd-4347 [001] 5231.043018: hrtimer_cancel: hrtimer=0xc0eb8798
       trace-cmd-4347 [001] 5231.043021: hrtimer_expire_entry: hrtimer=0xc0eb8798 now=5230120019365
       trace-cmd-4347 [001] 5231.043033: softirq_raise: vec=1 [action=TIMER]
       trace-cmd-4347 [001] 5231.043036: softirq_raise: vec=9 [action=RCU]
       trace-cmd-4347 [001] 5231.043039: sched_cpu_load: cpu: 1 : 0=1024 1=512 2=256 3=128 4=64
       trace-cmd-4347 [001] 5231.043041: sched_stat_runtime: comm=trace-cmd pid=4347 runtime=35083 [ns] vruntime=791546995846 [ns]
       trace-cmd-4347 [001] 5231.043044: sched_load_se: pid 4347 : period=48004 sum=7326 contrib=155 run=1
       trace-cmd-4347 [001] 5231.043047: sched_load_rq: cpu: 1 period=46405 sum=7279 decay=0
       trace-cmd-4347 [001] 5231.043051: sched_nohz_kick: cpu: 1 nr=1 busy=4
       trace-cmd-4347 [001] 5231.043054: hrtimer_expire_exit: hrtimer=0xc0eb8798
       trace-cmd-4347 [001] 5231.043055: hrtimer_start: hrtimer=0xc0eb8798 function=tick_sched_timer expires=5230130000000 softexpires=5230130000000
       trace-cmd-4347 [001] 5231.043059: irq_handler_exit: irq=27 ret=handled
       trace-cmd-4347 [001] 5231.043062: softirq_entry: vec=1 [action=TIMER]
       trace-cmd-4347 [001] 5231.043065: timer_cancel: timer=0xc069ad58
       trace-cmd-4347 [001] 5231.043068: timer_expire_entry: timer=0xc069ad58 function=errata2_function now=493012
       trace-cmd-4347 [001] 5231.043073: timer_start: timer=0xc069ad58 function=errata2_function expires=493032 [timeout=20]
       trace-cmd-4347 [001] 5231.043075: timer_expire_exit: timer=0xc069ad58
       trace-cmd-4347 [001] 5231.043076: timer_cancel: timer=0xef3e5b48
       trace-cmd-4347 [001] 5231.043077: timer_expire_entry: timer=0xef3e5b48 function=led_heartbeat_function now=493012
       trace-cmd-4347 [001] 5231.043081: timer_start: timer=0xef3e5b48 function=led_heartbeat_function expires=493019 [timeout=7]
       trace-cmd-4347 [001] 5231.043083: timer_expire_exit: timer=0xef3e5b48
       trace-cmd-4347 [001] 5231.043084: softirq_exit: vec=1 [action=TIMER]
       trace-cmd-4347 [001] 5231.043086: softirq_entry: vec=9 [action=RCU]
       trace-cmd-4347 [001] 5231.043095: sched_wake_affine: this 124108800 load 1024 prev 0 load 0
       trace-cmd-4347 [001] 5231.043098: sched_affine: task 2 prev 2 new 2
       trace-cmd-4347 [001] 5231.043102: sched_load_se: pid 10 : period=47570 sum=233 contrib=5 run=0
       trace-cmd-4347 [001] 5231.043104: sched_load_contrib: cpu: 2 runnable=5 blocked=11
       trace-cmd-4347 [001] 5231.043106: sched_stat_sleep: comm=rcu_sched pid=10 delay=18283000 [ns]
       trace-cmd-4347 [001] 5231.043108: sched_load_rq: cpu: 2 period=47266 sum=1031 decay=1
       trace-cmd-4347 [001] 5231.043112: sched_wakeup: 4347:?:? + 10:120:? rcu_sched [002] Success
       trace-cmd-4347 [001] 5231.043116: softirq_exit: vec=9 [action=RCU]
       trace-cmd-4347 [001] 5231.043136: sched_affine: task 3 prev 1 new 0
       trace-cmd-4347 [001] 5231.043139: sched_migrate_task: comm=trace-activity. pid=4344 prio=120 orig_cpu=3 dest_cpu=0
       trace-cmd-4347 [001] 5231.043144: sched_load_se: pid 4344 : period=48432 sum=0 contrib=0 run=0
       trace-cmd-4347 [001] 5231.043146: sched_load_contrib: cpu: 0 runnable=0 blocked=11
       trace-cmd-4347 [001] 5231.043148: sched_stat_sleep: comm=trace-activity. pid=4344 delay=2644164376 [ns]
       trace-cmd-4347 [001] 5231.043149: sched_load_rq: cpu: 0 period=46957 sum=752 decay=1
       trace-cmd-4347 [001] 5231.043151: sched_wakeup: 4347:?:? + 4344:120:? trace-activity. [000] Success
       trace-cmd-4347 [001] 5231.043157: sched_stat_runtime: comm=trace-cmd pid=4347 runtime=117750 [ns] vruntime=791547113596 [ns]
       trace-cmd-4347 [001] 5231.043158: sched_load_se: pid 4347 : period=48118 sum=7440 contrib=155 run=1
       trace-cmd-4347 [001] 5231.043159: sched_load_contrib: cpu: 1 runnable=0 blocked=155
       trace-cmd-4347 [001] 5231.043161: sched_load_rq: cpu: 1 period=46519 sum=7393 decay=0
       trace-cmd-4347 [001] 5231.043165: sched_load_rq: cpu: 1 period=46526 sum=7393 decay=0
       trace-cmd-4347 [001] 5231.043177: sched_sd_lb_stats: cpu: 1 level:1 balance=1 imb=0 busiest=0
       trace-cmd-4347 [001] 5231.043183: sched_sd_lb_stats: cpu: 1 level:2 balance=1 imb=0 busiest=0
       trace-cmd-4347 [001] 5231.043187: sched_switch: 4347:120:x ==> 0:120: swapper/1
          <idle>-0 [001] 5231.043192: sched_load_rq: cpu: 1 period=46526 sum=7393 decay=0
          <idle>-0 [001] 5231.043209: cpu_idle: state=1 cpu_id=1
          <idle>-0 [002] 5231.043412: cpu_idle: state=4294967295 cpu_id=2
          <idle>-0 [002] 5231.043437: sched_cpu_load: cpu: 2 : 0=0 1=0 2=9 3=29 4=36
          <idle>-0 [002] 5231.043447: hrtimer_start: hrtimer=0xc0ec1798 function=tick_sched_timer expires=5230130000000 softexpires=5230130000000
          <idle>-0 [002] 5231.043456: sched_load_rq: cpu: 2 period=47266 sum=1031 decay=0

[Daniel Lezcano (daniel-lezcano)]

Truncating the file to :

version = 6
cpus=5
       trace-cmd-4347 [001] 5231.042936: sched_process_exit: comm=trace-cmd pid=4347 prio=120
       trace-cmd-4347 [001] 5231.042987: sched_stat_runtime: comm=trace-cmd pid=4347 runtime=6912583 [ns] vruntime=791546941888 [ns]
       trace-cmd-4347 [001] 5231.042992: sched_load_se: pid 4347 : period=47970 sum=7292 contrib=23 run=1

produces the crash

[Daniel Lezcano (daniel-lezcano)]

The code is assuming the traces contains only cpu_idle traces.

The attached patch fixes the problem.