21 Nov, 2008

1 commit

  • Impact: make output of stack_trace complete if buffer overruns

    When read buffer overruns, the output of stack_trace isn't complete.

    When printing records with seq_printf in t_show, if the read buffer
    has overruned by the current record, then this record won't be
    printed to user space through read buffer, it will just be dropped in
    this printing.

    When next printing, t_start should return the "*pos"th record, which
    is the one dropped by previous printing, but it just returns
    (m->private + *pos)th record.

    Here we use a more sane method to implement seq_operations which can
    be found in kernel code. Thus we needn't initialize m->private.

    About testing, it's not easy to overrun read buffer, but we can use
    seq_printf to print more padding bytes in t_show, then it's easy to
    check whether or not records are lost.

    This commit has been tested on both condition of overrun and non
    overrun.

    Signed-off-by: Liming Wang
    Acked-by: Steven Rostedt
    Signed-off-by: Ingo Molnar

    Liming Wang
     

21 Oct, 2008

1 commit

  • The stack trace API does not record if the stack is not on the current
    task's stack. That is, if the stack is the interrupt stack or NMI stack,
    the output does not show. Also, the size of those stacks are not
    consistent with the size of the thread stack, this makes the calculation
    of the stack size usually bogus.

    This all confuses the stack tracer. I unfortunately do not have time to
    fix all these problems, but this patch does record the worst stack when
    the stack pointer is on the tasks stack (instead of bogus numbers).

    The patch simply returns if the stack pointer is not on the task's stack.

    Signed-off-by: Steven Rostedt
    Signed-off-by: Ingo Molnar

    Steven Rostedt
     

14 Oct, 2008

2 commits

  • This patch adds indexes into the stack that the functions in the
    stack dump were found at. As an added bonus, I also added a diff
    to show which function is the most notorious consumer of the stack.

    The output now looks like this:

    # cat /debug/tracing/stack_trace
    Depth Size Location (48 entries)
    ----- ---- --------
    0) 2476 212 blk_recount_segments+0x39/0x59
    1) 2264 12 bio_phys_segments+0x16/0x1d
    2) 2252 20 blk_rq_bio_prep+0x23/0xaf
    3) 2232 12 init_request_from_bio+0x74/0x77
    4) 2220 56 __make_request+0x294/0x331
    5) 2164 136 generic_make_request+0x34f/0x37d
    6) 2028 56 submit_bio+0xe7/0xef
    7) 1972 28 submit_bh+0xd1/0xf0
    8) 1944 112 block_read_full_page+0x299/0x2a9
    9) 1832 8 blkdev_readpage+0x14/0x16
    10) 1824 28 read_cache_page_async+0x7e/0x109
    11) 1796 16 read_cache_page+0x11/0x49
    12) 1780 32 read_dev_sector+0x3c/0x72
    13) 1748 48 read_lba+0x4d/0xaa
    14) 1700 168 efi_partition+0x85/0x61b
    15) 1532 72 rescan_partitions+0x10e/0x266
    16) 1460 40 do_open+0x1c7/0x24e
    17) 1420 292 __blkdev_get+0x79/0x84
    18) 1128 12 blkdev_get+0x12/0x14
    19) 1116 20 register_disk+0xd1/0x11e
    20) 1096 28 add_disk+0x34/0x90
    21) 1068 52 sd_probe+0x2b1/0x366
    22) 1016 20 driver_probe_device+0xa5/0x120
    23) 996 8 __device_attach+0xd/0xf
    24) 988 32 bus_for_each_drv+0x3e/0x68
    25) 956 24 device_attach+0x56/0x6c
    26) 932 16 bus_attach_device+0x26/0x4d
    27) 916 64 device_add+0x380/0x4b4
    28) 852 28 scsi_sysfs_add_sdev+0xa1/0x1c9
    29) 824 160 scsi_probe_and_add_lun+0x919/0xa2a
    30) 664 36 __scsi_add_device+0x88/0xae
    31) 628 44 ata_scsi_scan_host+0x9e/0x21c
    32) 584 28 ata_host_register+0x1cb/0x1db
    33) 556 24 ata_host_activate+0x98/0xb5
    34) 532 192 ahci_init_one+0x9bd/0x9e9
    35) 340 20 pci_device_probe+0x3e/0x5e
    36) 320 20 driver_probe_device+0xa5/0x120
    37) 300 20 __driver_attach+0x3f/0x5e
    38) 280 36 bus_for_each_dev+0x40/0x62
    39) 244 12 driver_attach+0x19/0x1b
    40) 232 28 bus_add_driver+0x9c/0x1af
    41) 204 28 driver_register+0x76/0xd2
    42) 176 20 __pci_register_driver+0x44/0x71
    43) 156 8 ahci_init+0x14/0x16
    44) 148 100 _stext+0x42/0x122
    45) 48 20 kernel_init+0x175/0x1dc
    46) 28 28 kernel_thread_helper+0x7/0x10

    The first column is simply an index starting from the inner most function
    and counting down to the outer most.

    The next column is the location that the function was found on the stack.

    The next column is the size of the stack for that function.

    Signed-off-by: Steven Rostedt
    Signed-off-by: Ingo Molnar

    Steven Rostedt
     
  • This is another tracer using the ftrace infrastructure, that examines
    at each function call the size of the stack. If the stack use is greater
    than the previous max it is recorded.

    You can always see (and set) the max stack size seen. By setting it
    to zero will start the recording again. The backtrace is also available.

    For example:

    # cat /debug/tracing/stack_max_size
    1856

    # cat /debug/tracing/stack_trace
    [] stack_trace_call+0x8f/0x101
    [] ftrace_call+0x5/0x8
    [] clocksource_get_next+0x12/0x48
    [] update_wall_time+0x538/0x6d1
    [] do_timer+0x23/0xb0
    [] tick_do_update_jiffies64+0xd9/0xf1
    [] tick_sched_timer+0x4a/0xad
    [] __run_hrtimer+0x3e/0x75
    [] hrtimer_interrupt+0xf1/0x154
    [] smp_apic_timer_interrupt+0x71/0x84
    [] apic_timer_interrupt+0x2d/0x34
    [] finish_task_switch+0x29/0xa0
    [] schedule+0x765/0x7be
    [] schedule_timeout+0x1b/0x90
    [] wait_for_common+0xab/0x101
    [] wait_for_completion+0x12/0x14
    [] blk_execute_rq+0x84/0x99
    [] scsi_execute+0xc2/0x105
    [] scsi_execute_req+0x57/0x7f
    [] sr_test_unit_ready+0x3e/0x97
    [] sr_media_change+0x43/0x205
    [] media_changed+0x48/0x77
    [] cdrom_media_changed+0x31/0x37
    [] sr_block_media_changed+0x16/0x18
    [] check_disk_change+0x1b/0x63
    [] cdrom_open+0x7a1/0x806
    [] sr_block_open+0x78/0x8d
    [] do_open+0x90/0x257
    [] blkdev_open+0x2d/0x56
    [] __dentry_open+0x14d/0x23c
    [] nameidata_to_filp+0x24/0x38
    [] do_filp_open+0x347/0x626
    [] do_sys_open+0x47/0xbc
    [] sys_open+0x23/0x2b
    [] sysenter_do_call+0x12/0x26

    I've tested this on both x86_64 and i386.

    Signed-off-by: Steven Rostedt
    Cc: Peter Zijlstra
    Cc: Andrew Morton
    Cc: Linus Torvalds
    Signed-off-by: Ingo Molnar

    Steven Rostedt