[3.4-rc3] Thread overran stack, or stack corrupted

[3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

My syscall fuzzer started showing up some cases where it we seem to be
overrunning the stack.  I added a WARN_ON when the stack is really low,
to see if there's a deep call trace, but it's not really telling me much ..

	Dave

[ 5393.970003] trinity used greatest stack depth: 1048 bytes left
[ 5419.095374] trinity used greatest stack depth: 8 bytes left
[ 5419.095864] ------------[ cut here ]------------
[ 5419.096611] WARNING: at kernel/exit.c:892 do_exit+0xb77/0xb80()
[ 5419.097830] Hardware name: Precision WorkStation 490    
[ 5419.098908] Modules linked in: scsi_transport_iscsi ipt_ULOG dccp_ipv6 tun hidp dccp_ipv4 dccp bnep can_raw sctp binfmt_misc l2tp_ppp l2tp_netlink l2tp_core can_bcm ip_queue rfcomm cmtp kernelcapi af_802154 phonet bluetooth rfkill can pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose ax25 atm appletalk ipx p8022 psnap llc p8023 nfs fscache auth_rpcgss nfs_acl lockd ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables btrfs zlib_deflate libcrc32c dm_mirror dm_region_hash dm_log coretemp raid0 ppdev dcdbas usb_debug microcode snd_hda_codec_idt snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm serio_raw i2c_i801 pcspkr iTCO_wdt iTCO_vendor_support tg3 snd_timer i5000_edac snd edac_core soundcore snd_page_alloc i5k_amb shpchp parport_pc parport sunrpc firewire_ohci firewire_core crc_itu_t floppy nouveau ttm drm_kms_helper drm i2c_core mxm_wmi video wmi [last unloaded: scsi_wait_scan]
[ 5419.107431] Pid: 841, comm: trinity Tainted: G        W    3.4.0-rc3+ #45
[ 5419.108688] Call Trace:
[ 5419.109803]  [<ffffffff81065a9f>] warn_slowpath_common+0x7f/0xc0
[ 5419.111023]  [<ffffffff81065afa>] warn_slowpath_null+0x1a/0x20
[ 5419.112463]  [<ffffffff8106bba7>] do_exit+0xb77/0xb80
[ 5419.113525]  [<ffffffff8106beff>] do_group_exit+0x4f/0xc0
[ 5419.114946]  [<ffffffff8107eace>] get_signal_to_deliver+0x20e/0x880
[ 5419.116063]  [<ffffffff8107bda0>] ? __send_signal+0x150/0x7f0
[ 5419.117469]  [<ffffffff8108b820>] ? task_tgid_nr_ns+0x20/0x20
[ 5419.118805]  [<ffffffff8101b315>] do_signal+0x65/0x5d0
[ 5419.120161]  [<ffffffff816aed01>] ? _raw_spin_unlock_irq+0x41/0x70
[ 5419.121662]  [<ffffffff8107f312>] ? set_current_blocked+0x52/0x60
[ 5419.122583]  [<ffffffff813360de>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 5419.123994]  [<ffffffff816aed01>] ? _raw_spin_unlock_irq+0x41/0x70
[ 5419.125064]  [<ffffffff8101b905>] do_notify_resume+0x65/0x80
[ 5419.126505]  [<ffffffff813360de>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 5419.127668]  [<ffffffff816b74e2>] int_signal+0x12/0x17
[ 5419.129118] ---[ end trace bed9ff07ecc14c9d ]---
[ 5419.143061] BUG: unable to handle kernel NULL pointer dereference at 0000000000000048
[ 5419.143712] IP: [<ffffffff8106b230>] do_exit+0x200/0xb80
[ 5419.144004] PGD 202d44067 PUD 201876067 PMD 0 
[ 5419.144004] Thread overran stack, or stack corrupted
[ 5419.144004] Oops: 0000 [#1] PREEMPT SMP 
[ 5419.144004] CPU 0 
[ 5419.144004] Modules linked in: scsi_transport_iscsi ipt_ULOG dccp_ipv6 tun hidp dccp_ipv4 dccp bnep can_raw sctp binfmt_misc l2tp_ppp l2tp_netlink l2tp_core can_bcm ip_queue rfcomm cmtp kernelcapi af_802154 phonet bluetooth rfkill can pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose ax25 atm appletalk ipx p8022 psnap llc p8023 nfs fscache auth_rpcgss nfs_acl lockd ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables btrfs zlib_deflate libcrc32c dm_mirror dm_region_hash dm_log coretemp raid0 ppdev dcdbas usb_debug microcode snd_hda_codec_idt snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm serio_raw i2c_i801 pcspkr iTCO_wdt iTCO_vendor_support tg3 snd_timer i5000_edac snd edac_core soundcore snd_page_alloc i5k_amb shpchp parport_pc parport sunrpc firewire_ohci firewire_core crc_itu_t floppy nouveau ttm drm_kms_helper drm i2c_core mxm_wmi video wmi [last unloaded: scsi_wait_scan]
[ 5419.144004] 
[ 5419.144004] Pid: 841, comm: trinity Tainted: G        W    3.4.0-rc3+ #45 Dell Inc.                 Precision WorkStation 490    /0DT031
[ 5419.144004] RIP: 0010:[<ffffffff8106b230>]  [<ffffffff8106b230>] do_exit+0x200/0xb80
[ 5419.144004] RSP: 0018:ffff88006f2dfcc8  EFLAGS: 00010246
[ 5419.144004] RAX: 0000000000000000 RBX: ffff880028820000 RCX: 0000000000000030
[ 5419.144004] RDX: 0000000000000030 RSI: 0000000000000001 RDI: 0000000000000000
[ 5419.144004] RBP: ffff88006f2dfd48 R08: 0000000000000000 R09: 0000000000000001
[ 5419.144004] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000008
[ 5419.144004] R13: 00007ffffffff000 R14: 0000000000000349 R15: ffff880028820000
[ 5419.144004] FS:  00007f8742d4f700(0000) GS:ffff880236600000(0000) knlGS:0000000000000000
[ 5419.144004] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 5419.144004] CR2: 0000000000000048 CR3: 00000001090fd000 CR4: 00000000000007f0
[ 5419.144004] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 5419.144004] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 5419.144004] Process trinity (pid: 841, threadinfo ffff88006f2de000, task ffff880028820000)
[ 5419.144004] Stack:
[ 5419.144004]  0000000000000000 0000000128820000 0000000000000000 00007fff00000000
[ 5419.144004]  dead4ead00000000 ffffffffffffffff ffffffffffffffff ffffffff829bce50
[ 5419.144004]  0000000000000000 0000000000000000 ffffffff819c7001 0000000000000086
[ 5419.144004] Call Trace:
[ 5419.144004]  [<ffffffff8106beff>] do_group_exit+0x4f/0xc0
[ 5419.144004]  [<ffffffff8107eace>] get_signal_to_deliver+0x20e/0x880
[ 5419.144004]  [<ffffffff8107bda0>] ? __send_signal+0x150/0x7f0
[ 5419.144004]  [<ffffffff8108b820>] ? task_tgid_nr_ns+0x20/0x20
[ 5419.144004]  [<ffffffff8101b315>] do_signal+0x65/0x5d0
[ 5419.144004]  [<ffffffff816aed01>] ? _raw_spin_unlock_irq+0x41/0x70
[ 5419.144004]  [<ffffffff8107f312>] ? set_current_blocked+0x52/0x60
[ 5419.144004]  [<ffffffff813360de>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 5419.144004]  [<ffffffff816aed01>] ? _raw_spin_unlock_irq+0x41/0x70
[ 5419.194777]  [<ffffffff8101b905>] do_notify_resume+0x65/0x80
[ 5419.194777]  [<ffffffff813360de>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 5419.194777]  [<ffffffff816b74e2>] int_signal+0x12/0x17
[ 5419.194777] Code: df e8 55 74 0e 00 be 01 00 00 00 48 89 df e8 d8 3e 08 00 44 8b 55 8c 45 85 d2 0f 85 49 05 00 00 48 8b 43 08 49 89 df 48 8b 40 08 <48> 8b 78 48 e8 37 37 07 00 48 89 df e8 7f fd 3a 00 48 89 df e8 
[ 5419.194777] RIP  [<ffffffff8106b230>] do_exit+0x200/0xb80
[ 5419.194777]  RSP <ffff88006f2dfcc8>
[ 5419.194777] CR2: 0000000000000048

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Linus Torvalds]

On Tue, Apr 17, 2012 at 10:21 AM, Dave Jones <davej@redhat.com> wrote:
> My syscall fuzzer started showing up some cases where it we seem to be
> overrunning the stack.  I added a WARN_ON when the stack is really low,
> to see if there's a deep call trace, but it's not really telling me much ..

You seem to have added the WARN_ON() to check_stack_usage() itself.

That's not very useful, because it uses the *current* stack pointer.
Instead, how about just calling "show_trace()" with the actual lowest
stack pointer at that point? That should show you the stack as it was
when it was at its lowest, and that could actually be useful.

IOW, just something like

    show_trace(NULL, NULL, (void *)end_of_stack(p) + lowest_to_date, NULL);

Or something kind of like that. Yes?

                           Linus

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Tue, Apr 17, 2012 at 01:20:51PM -0700, Linus Torvalds wrote:
 > On Tue, Apr 17, 2012 at 10:21 AM, Dave Jones <davej@redhat.com> wrote:
 > > My syscall fuzzer started showing up some cases where it we seem to be
 > > overrunning the stack.  I added a WARN_ON when the stack is really low,
 > > to see if there's a deep call trace, but it's not really telling me much ..
 > 
 > You seem to have added the WARN_ON() to check_stack_usage() itself.
 > 
 > That's not very useful, because it uses the *current* stack pointer.
 > Instead, how about just calling "show_trace()" with the actual lowest
 > stack pointer at that point? That should show you the stack as it was
 > when it was at its lowest, and that could actually be useful.
 > 
 > IOW, just something like
 > 
 >     show_trace(NULL, NULL, (void *)end_of_stack(p) + lowest_to_date, NULL);
 > 
 > Or something kind of like that. Yes?

Ok, this builds. I'll run with this for a while, and see what falls out.

thanks,

	Dave

--- linux/kernel/exit.c	2012-03-29 22:45:18.912241586 -0400
+++ linux/kernel/exit.c	2012-04-17 16:29:54.473445787 -0400
@@ -871,7 +871,7 @@
 }
 
 #ifdef CONFIG_DEBUG_STACK_USAGE
-static void check_stack_usage(void)
+static void check_stack_usage(struct task_struct *p)
 {
 	static DEFINE_SPINLOCK(low_water_lock);
 	static int lowest_to_date = THREAD_SIZE;
@@ -888,11 +888,13 @@
 				"left\n",
 				current->comm, free);
 		lowest_to_date = free;
+		if (lowest_to_date < 512)
+			show_trace(NULL, NULL, (long unsigned int *)end_of_stack(p) + lowest_to_date, 0);
 	}
 	spin_unlock(&low_water_lock);
 }
 #else
-static inline void check_stack_usage(void) {}
+static inline void check_stack_usage(struct task_struct *p) {}
 #endif
 
 void do_exit(long code)
@@ -987,7 +989,7 @@
 	exit_shm(tsk);
 	exit_files(tsk);
 	exit_fs(tsk);
-	check_stack_usage();
+	check_stack_usage(tsk);
 	exit_thread();
 
 	/*

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Linus Torvalds]

On Tue, Apr 17, 2012 at 1:32 PM, Dave Jones <davej@redhat.com> wrote:
>
> Ok, this builds. I'll run with this for a while, and see what falls out.

So assuming that works and doesn't have some silly thinko in it, I
think it is a worthwhile addition to the whole stack debugging thing.
Right now, the message about "process xyz used most stack, x bytes
free" really is pretty useless. If it were to actually show "hey, this
was the deepest actual stack chain", that sounds quite interesting.

Of course, if the stack is largely used by some leaf function that
just has a big stack frame, that won't show up in the stack trace, but
that's presumably not the worst worry. And hopefully the caller of
that would still be pretty deep and show up without having been
overwritten.

                     Linus

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Tue, Apr 17, 2012 at 06:36:00PM -0700, Linus Torvalds wrote:
> On Tue, Apr 17, 2012 at 1:32 PM, Dave Jones <davej@redhat.com> wrote:
> >
> > Ok, this builds. I'll run with this for a while, and see what falls out.
> 
> So assuming that works and doesn't have some silly thinko in it, I
> think it is a worthwhile addition to the whole stack debugging thing.
> Right now, the message about "process xyz used most stack, x bytes
> free" really is pretty useless. If it were to actually show "hey, this
> was the deepest actual stack chain", that sounds quite interesting.
> 
> Of course, if the stack is largely used by some leaf function that
> just has a big stack frame, that won't show up in the stack trace, but
> that's presumably not the worst worry. And hopefully the caller of
> that would still be pretty deep and show up without having been
> overwritten.

Note we have something that checks the stack, even on leaf functions.

Enable CONFIG_STACK_TRACER

and then enable it with the following:

# echo 1 > /proc/sys/kernel/stack_tracer_enabled
# cat /sys/kernel/debug/tracing/stack_trace
        Depth    Size   Location    (40 entries)
        -----    ----   --------
  0)     3056     208   select_task_rq_fair+0x30b/0x8b2
  1)     2848      96   try_to_wake_up+0xc7/0x30e
  2)     2752      16   default_wake_function+0x12/0x14
  3)     2736      32   autoremove_wake_function+0x16/0x39
  4)     2704      80   __wake_up_common+0x4e/0x84
  5)     2624      64   __wake_up+0x39/0x4d
  6)     2560      64   insert_work+0x8e/0x9b
  7)     2496      48   __queue_work+0x2f/0x41
  8)     2448      16   queue_work_on+0x48/0x4f
  9)     2432      16   queue_work+0x1f/0x21
 10)     2416      16   queue_delayed_work+0x13/0x28
 11)     2400      32   ata_pio_queue_task+0x35/0x39
 12)     2368      32   ata_sff_qc_issue+0x1e9/0x222
 13)     2336      96   ata_qc_issue+0x25e/0x29c
 14)     2240      80   __ata_scsi_queuecmd+0x193/0x1ef
 15)     2160      80   ata_scsi_queuecmd+0x59/0x93
 16)     2080      48   scsi_dispatch_cmd+0x1b1/0x233
 17)     2032      96   scsi_request_fn+0x385/0x4d8
 18)     1936      32   __generic_unplug_device+0x32/0x36
 19)     1904      48   blk_execute_rq_nowait+0x77/0x9e
 20)     1856     176   blk_execute_rq+0xa6/0xde
 21)     1680      80   scsi_execute+0xf6/0x148
 22)     1600     128   scsi_execute_req+0xa9/0xdb
 23)     1472      96   sr_test_unit_ready+0x65/0xcb
 24)     1376     160   sr_media_change+0x9f/0x2cd
 25)     1216      48   media_changed+0x54/0x8c
 26)     1168      16   cdrom_media_changed+0x31/0x37
 27)     1152      16   sr_block_media_changed+0x19/0x1b
 28)     1136      32   check_disk_change+0x29/0x5b
 29)     1104     208   cdrom_open+0x3d7/0x4b2
 30)      896      64   sr_block_open+0x90/0xad
 31)      832      96   __blkdev_get+0xd3/0x358
 32)      736      16   blkdev_get+0x10/0x12
 33)      720      48   blkdev_open+0x76/0xac
 34)      672      96   __dentry_open+0x199/0x2d2
 35)      576      32   nameidata_to_filp+0x42/0x53
 36)      544     320   do_filp_open+0x4f1/0x9d6
 37)      224      80   do_sys_open+0x63/0x10f
 38)      144      16   sys_open+0x20/0x22
 39)      128     128   system_call_fastpath+0x16/0x1b


You can also use trace-cmd to handle this:

# trace-cmd stack --start
# trace-cmd stack
        Depth    Size   Location    (24 entries)
        -----    ----   --------
  0)     2480      48   lock_timer_base+0x2c/0x52
  1)     2432      96   __mod_timer+0x3e/0x15e
  2)     2336      16   mod_timer_pending+0x15/0x17
  3)     2320      64   __nf_ct_refresh_acct+0x60/0xd9
  4)     2256     272   tcp_packet+0xe17/0x10e7
  5)     1984     224   nf_conntrack_in+0x687/0x86e
  6)     1760      16   ipv4_conntrack_local+0x40/0x49
  7)     1744      80   nf_iterate+0x46/0x89
  8)     1664     112   nf_hook_slow+0x6a/0xcb
  9)     1552      32   nf_hook_thresh.clone.0+0x41/0x4a
 10)     1520      16   __ip_local_out+0x7e/0x80
 11)     1504      32   ip_local_out+0x16/0x29
 12)     1472     176   ip_queue_xmit+0x30e/0x37f
 13)     1296     128   tcp_transmit_skb+0x64d/0x68b
 14)     1168     144   tcp_write_xmit+0x80d/0x8fc
 15)     1024      32   __tcp_push_pending_frames+0x2f/0x5d
 16)      992      16   tcp_push+0x88/0x8a
 17)      976     176   tcp_sendmsg+0x77b/0x876
 18)      800      64   __sock_sendmsg+0x61/0x6c
 19)      736     176   sock_aio_write+0xc0/0xd4
 20)      560     304   do_sync_write+0xe8/0x125
 21)      256      64   vfs_write+0xc1/0x10b
 22)      192      64   sys_write+0x4a/0x6e
 23)      128     128   system_call_fastpath+0x16/0x1b
# trace-cmd stack --stop

This also shows you the size of stack each function took up.

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Tue, Apr 17, 2012 at 10:27:05PM -0400, Steven Rostedt wrote:

 > Note we have something that checks the stack, even on leaf functions.
 > 
 > Enable CONFIG_STACK_TRACER
 > 
 > and then enable it with the following:
 > 
 > # echo 1 > /proc/sys/kernel/stack_tracer_enabled
 > # cat /sys/kernel/debug/tracing/stack_trace
 >         Depth    Size   Location    (40 entries)
 >         -----    ----   --------
 >   0)     3056     208   select_task_rq_fair+0x30b/0x8b2
 >   1)     2848      96   try_to_wake_up+0xc7/0x30e

That looks handy. Doesn't seem to work for me though on my test box.
(config option is enabled.)

# echo 1 > /proc/sys/kernel/stack_tracer_enabled
# cat /sys/kernel/debug/tracing/stack_trace
        Depth    Size   Location    (-1 entries)
        -----    ----   --------

That's all she wrote.

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Tue, Apr 17, 2012 at 06:36:00PM -0700, Linus Torvalds wrote:
 > On Tue, Apr 17, 2012 at 1:32 PM, Dave Jones <davej@redhat.com> wrote:
 > >
 > > Ok, this builds. I'll run with this for a while, and see what falls out.
 > 
 > So assuming that works and doesn't have some silly thinko in it, I
 > think it is a worthwhile addition to the whole stack debugging thing.
 > Right now, the message about "process xyz used most stack, x bytes
 > free" really is pretty useless. If it were to actually show "hey, this
 > was the deepest actual stack chain", that sounds quite interesting.
 > 
 > Of course, if the stack is largely used by some leaf function that
 > just has a big stack frame, that won't show up in the stack trace, but
 > that's presumably not the worst worry. And hopefully the caller of
 > that would still be pretty deep and show up without having been
 > overwritten.

So now that I'm instrumenting it, it's taking a lot longer to trigger
(how typical). Almost 6 hours in though, it's down to 72 bytes, and spewed
the traces below, which look pretty.. deep.
I'll leave it run overnight, to see if it triggers the 'overran stack' trace
again, but I suspect it'll look very similar to the ones shown below.

	Dave


[ 2496.639872] trinity used greatest stack depth: 1560 bytes left
[ 3604.156895] trinity used greatest stack depth: 1352 bytes left
[ 5448.499455] trinity used greatest stack depth: 1264 bytes left
[ 9751.238389] trinity used greatest stack depth: 864 bytes left
[15000.946998] trinity used greatest stack depth: 800 bytes left
[15079.438172] trinity used greatest stack depth: 656 bytes left
[21137.019557] trinity used greatest stack depth: 456 bytes left
[21137.019982] Call Trace:
[21137.020353]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.020765]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.021718]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21137.022231]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21137.023327]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21137.023954]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21137.024989]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21137.025704]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.026157]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21137.027200]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21137.027710]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.028708]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.029558]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.030053]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21137.031017]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21137.031669]  [<ffffffff810a847a>] ? cpuacct_charge+0x2a/0x240
[21137.032782]  [<ffffffff8109c04f>] ? finish_task_switch+0x3f/0x120
[21137.033295]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.033967]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21137.035386]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21137.035872]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21137.036376]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21137.037401]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21137.039119]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21137.040116]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21137.041752]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21137.042494]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21137.043751]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21137.044302]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21137.044796]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21137.045883]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21137.046391]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21137.046838]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21137.047369]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21137.048232]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21137.049577]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21137.050115]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21137.050879]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.051399]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21137.052206]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.053551]  [<ffffffff816ac00f>] ? __mutex_unlock_slowpath+0x14f/0x190
[21137.054026]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21137.055167]  [<ffffffff816ac05e>] ? mutex_unlock+0xe/0x10
[21137.055655]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.056156]  [<ffffffff81380165>] ? bit_putcs+0x2e5/0x560
[21137.057035]  [<ffffffff814ae4cc>] ? qtd_fill+0xc/0xc0
[21137.058041]  [<ffffffff816ac05e>] ? mutex_unlock+0xe/0x10
[21137.058644]  [<ffffffff814b5609>] ? qh_append_tds+0xf9/0x690
[21137.059789]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.060326]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.061115]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21137.062180]  [<ffffffff816ac00f>] ? __mutex_unlock_slowpath+0x14f/0x190
[21137.062731]  [<ffffffff81050869>] ? __phys_addr+0x9/0x50
[21137.063832]  [<ffffffff81345fb8>] ? swiotlb_dma_mapping_error+0x18/0x30
[21137.064337]  [<ffffffff81499101>] ? usb_hcd_map_urb_for_dma+0x531/0x5b0
[21137.065074]  [<ffffffff813806be>] ? soft_cursor+0x1ce/0x270
[21137.065919]  [<ffffffffa00c73d2>] ? nouveau_fbcon_fillrect+0xc2/0x110 [nouveau]
[21137.066758]  [<ffffffff8149922f>] ? usb_hcd_submit_urb+0xaf/0x860
[21137.068183]  [<ffffffff8137fe3b>] ? bit_cursor+0x60b/0x650
[21137.068702]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.069802]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21137.070531]  [<ffffffff814d336e>] ? usb_serial_generic_write_start+0x22e/0x270
[21137.071113]  [<ffffffff81090667>] ? kfifo_copy_in+0x77/0x90
[21137.071588]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.072813]  [<ffffffff814d3664>] ? usb_serial_generic_write+0x84/0xd0
[21137.073346]  [<ffffffff814d4220>] ? usb_console_write+0x110/0x250
[21137.074210]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21137.075545]  [<ffffffff816af5b4>] ? retint_restore_args+0x13/0x13
[21137.076036]  [<ffffffff81066ed9>] ? vprintk+0x389/0x600
[21137.076738]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21137.078066]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21137.078542]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21137.079263]  [<ffffffff816a1b67>] ? printk+0x51/0x53
[21137.080295]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21137.080839]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21137.082013]  [<ffffffff810e3145>] ? is_module_text_address+0x55/0x60
[21137.082566]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21137.083458]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21137.084787]  [<ffffffff8101d54f>] ? dump_trace+0x17f/0x2f0
[21137.085246]  [<ffffffff8101ea0c>] show_trace_log_lvl+0x5c/0x80
[21137.085962]  [<ffffffff8101ea45>] show_trace+0x15/0x20
[21137.087188]  [<ffffffff8106bbaf>] do_exit+0xb7f/0xb90
[21137.087629]  [<ffffffff8106bf0f>] do_group_exit+0x4f/0xc0
[21137.088388]  [<ffffffff8107eade>] get_signal_to_deliver+0x20e/0x880
[21137.089757]  [<ffffffff8107bdb0>] ? __send_signal+0x150/0x7f0
[21137.090202]  [<ffffffff811177de>] ? __rcu_read_unlock+0xe/0xa0
[21137.091126]  [<ffffffff8108b830>] ? task_tgid_nr_ns+0x20/0x20
[21137.091701]  [<ffffffff8101b315>] do_signal+0x65/0x5d0
[21137.092560]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21137.094242]  [<ffffffff8107f322>] ? set_current_blocked+0x52/0x60
[21137.095524]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21137.096777]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21137.098541]  [<ffffffff8101b905>] do_notify_resume+0x65/0x80
[21137.099113]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21137.099686]  [<ffffffff816b73a2>] int_signal+0x12/0x17
[21162.880562] trinity used greatest stack depth: 280 bytes left
[21162.881249] Call Trace:
[21162.883712]  [<ffffffff811605d4>] ? free_pages_prepare+0x1b4/0x290
[21162.884545]  [<ffffffff811b8e20>] ? mem_cgroup_recursive_stat+0x70/0x70
[21162.885217]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21162.885673]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.886320]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.887113]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.887736]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.888600]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21162.889674]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.890501]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.891421]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.892022]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21162.893069]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21162.893717]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.895053]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.895490]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.896200]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21162.897624]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.898462]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.899162]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.899775]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21162.900428]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.901518]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.902104]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21162.902917]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21162.904239]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21162.904675]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21162.905402]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.906195]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.907352]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.907863]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.908965]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21162.909507]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.910322]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.911307]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.911875]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21162.912953]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21162.913528]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.914363]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.915689]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.916138]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21162.916812]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.918125]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.918571]  [<ffffffff810ccf2d>] ? trace_hardirqs_off+0xd/0x10
[21162.919272]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21162.920287]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.920898]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.921917]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.922564]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21162.923857]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21162.924318]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.925040]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.926251]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.926741]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21162.927492]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21162.928929]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.929416]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.930157]  [<ffffffff8143d66a>] ? scsi_pool_alloc_command+0x4a/0x80
[21162.930697]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.931644]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.932587]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21162.933116]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.934177]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.934712]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21162.935736]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21162.936318]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21162.937110]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21162.938422]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21162.938888]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21162.939999]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21162.940457]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21162.941461]  [<ffffffffa037d202>] ? alloc_extent_state+0x32/0x1c0 [btrfs]
[21162.941912]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.942806]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.943406]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.944445]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21162.944898]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.945692]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21162.946692]  [<ffffffff816ac00f>] ? __mutex_unlock_slowpath+0x14f/0x190
[21162.947319]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.948440]  [<ffffffff816ac05e>] ? mutex_unlock+0xe/0x10
[21162.948933]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.949744]  [<ffffffff814ae4cc>] ? qtd_fill+0xc/0xc0
[21162.950960]  [<ffffffff816ac05e>] ? mutex_unlock+0xe/0x10
[21162.951404]  [<ffffffff814b5609>] ? qh_append_tds+0xf9/0x690
[21162.952143]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.953576]  [<ffffffffa00a5e86>] ? nouveau_dma_wait+0x16/0x5b0 [nouveau]
[21162.954397]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.955171]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21162.955803]  [<ffffffff816ac00f>] ? __mutex_unlock_slowpath+0x14f/0x190
[21162.956249]  [<ffffffffa00c7180>] ? nouveau_fbcon_imageblit+0x90/0x110 [nouveau]
[21162.957053]  [<ffffffff81050869>] ? __phys_addr+0x9/0x50
[21162.958037]  [<ffffffff81345fb8>] ? swiotlb_dma_mapping_error+0x18/0x30
[21162.958692]  [<ffffffff81499101>] ? usb_hcd_map_urb_for_dma+0x531/0x5b0
[21162.960092]  [<ffffffffa00c73d2>] ? nouveau_fbcon_fillrect+0xc2/0x110 [nouveau]
[21162.961206]  [<ffffffff8149922f>] ? usb_hcd_submit_urb+0xaf/0x860
[21162.962185]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.962649]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21162.963072]  [<ffffffff814d336e>] ? usb_serial_generic_write_start+0x22e/0x270
[21162.963640]  [<ffffffff81090667>] ? kfifo_copy_in+0x77/0x90
[21162.964801]  [<ffffffff814d3664>] ? usb_serial_generic_write+0x84/0xd0
[21162.965701]  [<ffffffff814d4220>] ? usb_console_write+0x110/0x250
[21162.966264]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21162.967431]  [<ffffffff816af5b4>] ? retint_restore_args+0x13/0x13
[21162.967995]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21162.969424]  [<ffffffff81066ed9>] ? vprintk+0x389/0x600
[21162.969877]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21162.970836]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21162.971524]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21162.972502]  [<ffffffff816a1b67>] ? printk+0x51/0x53
[21162.973192]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21162.974558]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21162.975000]  [<ffffffff810e3145>] ? is_module_text_address+0x55/0x60
[21162.976554]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21162.978461]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21162.978907]  [<ffffffff8101d54f>] ? dump_trace+0x17f/0x2f0
[21162.979574]  [<ffffffff8101ea0c>] show_trace_log_lvl+0x5c/0x80
[21162.979977]  [<ffffffff8101ea45>] show_trace+0x15/0x20
[21162.980819]  [<ffffffff8106bbaf>] do_exit+0xb7f/0xb90
[21162.982280]  [<ffffffff8106bf0f>] do_group_exit+0x4f/0xc0
[21162.982729]  [<ffffffff8107eade>] get_signal_to_deliver+0x20e/0x880
[21162.983859]  [<ffffffff8107bdb0>] ? __send_signal+0x150/0x7f0
[21162.984789]  [<ffffffff811177de>] ? __rcu_read_unlock+0xe/0xa0
[21162.986147]  [<ffffffff8108b830>] ? task_tgid_nr_ns+0x20/0x20
[21162.986616]  [<ffffffff8101b315>] do_signal+0x65/0x5d0
[21162.987316]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21162.987761]  [<ffffffff8107f322>] ? set_current_blocked+0x52/0x60
[21162.988680]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21162.989521]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21162.990238]  [<ffffffff8101b905>] do_notify_resume+0x65/0x80
[21162.991283]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21162.992209]  [<ffffffff816b73a2>] int_signal+0x12/0x17
[21171.661403] trinity used greatest stack depth: 72 bytes left
[21171.661978] Call Trace:
[21171.662403]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.663400]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.663856]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.664895]  [<ffffffff8101d559>] ? dump_trace+0x189/0x2f0
[21171.665647]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.666475]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.667570]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.668140]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.669035]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.670080]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.670728]  [<ffffffff8133db38>] ? debug_check_no_obj_freed+0x88/0x230
[21171.671778]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.672654]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21171.673285]  [<ffffffff816aec2a>] ? _raw_spin_unlock_irqrestore+0x4a/0x90
[21171.674667]  [<ffffffff8133dc2f>] ? debug_check_no_obj_freed+0x17f/0x230
[21171.675138]  [<ffffffff811605d4>] ? free_pages_prepare+0x1b4/0x290
[21171.675722]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.676895]  [<ffffffff81160c0e>] ? free_hot_cold_page_list+0x5e/0x1a0
[21171.677493]  [<ffffffff811bd0be>] ? mem_cgroup_uncharge_cache_page+0x1e/0x30
[21171.678457]  [<ffffffff8116d2da>] ? shrink_page_list+0x69a/0xac0
[21171.679757]  [<ffffffffa0090205>] ? ttm_dma_pool_mm_shrink+0x105/0x190 [ttm]
[21171.680287]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.680886]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21171.682085]  [<ffffffff811c668d>] ? put_super+0x1d/0x40
[21171.682662]  [<ffffffffa0090205>] ? ttm_dma_pool_mm_shrink+0x105/0x190 [ttm]
[21171.684097]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.684555]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21171.685408]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21171.685982]  [<ffffffff811c66a1>] ? put_super+0x31/0x40
[21171.687135]  [<ffffffff8111d081>] ? delayacct_end+0x71/0xa0
[21171.687675]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.688548]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.689918]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21171.690414]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.690989]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.691842]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.693212]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21171.693704]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21171.694509]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.695534]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.696104]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21171.697232]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.697821]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.699117]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.699618]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21171.700421]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21171.701746]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21171.702219]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21171.703277]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21171.703880]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21171.704810]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21171.706108]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21171.706581]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.707560]  [<ffffffff8115a5d5>] ? mempool_alloc_slab+0x15/0x20
[21171.708156]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.709302]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.709803]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21171.710925]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.711544]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.712409]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.713734]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.714231]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.715304]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.716149]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.716902]  [<ffffffff811a9eae>] ? deactivate_slab+0x3ce/0x5f0
[21171.717513]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.718660]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.719208]  [<ffffffff810a2981>] ? get_parent_ip+0x11/0x50
[21171.720049]  [<ffffffff816b30ad>] ? sub_preempt_count+0x9d/0xd0
[21171.721357]  [<ffffffff816aeca5>] ? _raw_spin_unlock+0x35/0x60
[21171.721902]  [<ffffffff811aa02c>] ? deactivate_slab+0x54c/0x5f0
[21171.722939]  [<ffffffffa03a312e>] ? btrfs_add_delayed_tree_ref+0x8e/0x1d0 [btrfs]
[21171.723535]  [<ffffffffa03a312e>] ? btrfs_add_delayed_tree_ref+0x8e/0x1d0 [btrfs]
[21171.724412]  [<ffffffffa03a312e>] ? btrfs_add_delayed_tree_ref+0x8e/0x1d0 [btrfs]
[21171.725889]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21171.726373]  [<ffffffffa03a312e>] ? btrfs_add_delayed_tree_ref+0x8e/0x1d0 [btrfs]
[21171.726906]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.728478]  [<ffffffff8133d384>] ? debug_object_activate+0x84/0x1a0
[21171.729179]  [<ffffffff8133cf32>] ? __debug_object_init+0xa2/0x410
[21171.729714]  [<ffffffff8133d9d7>] ? debug_object_active_state+0x67/0x140
[21171.730938]  [<ffffffff811630fb>] ? __set_page_dirty_nobuffers+0x7b/0x1a0
[21171.731420]  [<ffffffff8109c04f>] ? finish_task_switch+0x3f/0x120
[21171.732387]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.732991]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21171.734109]  [<ffffffff8109c08c>] ? finish_task_switch+0x7c/0x120
[21171.734748]  [<ffffffff8109c04f>] ? finish_task_switch+0x3f/0x120
[21171.735648]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.737086]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.737554]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.738120]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.739435]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.739889]  [<ffffffff810e3123>] ? is_module_text_address+0x33/0x60
[21171.740964]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.741509]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.742293]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.743706]  [<ffffffff8101d559>] ? dump_trace+0x189/0x2f0
[21171.744207]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.744857]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.746371]  [<ffffffffa037d5aa>] ? free_extent_state+0x5a/0x1b0 [btrfs]
[21171.746883]  [<ffffffff811a7fcc>] ? set_track+0xac/0x1a0
[21171.747827]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.748485]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.749276]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.749859]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.750886]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.751523]  [<ffffffff8108ba29>] ? debug_lockdep_rcu_enabled+0x9/0x40
[21171.752646]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.753201]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21171.754044]  [<ffffffff81198c0e>] ? dma_pool_alloc+0x22e/0x340
[21171.755396]  [<ffffffffa00c7180>] ? nouveau_fbcon_imageblit+0x90/0x110 [nouveau]
[21171.755872]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.756904]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.757514]  [<ffffffff814ae4cc>] ? qtd_fill+0xc/0xc0
[21171.758338]  [<ffffffff814b5609>] ? qh_append_tds+0xf9/0x690
[21171.759728]  [<ffffffffa00a5e86>] ? nouveau_dma_wait+0x16/0x5b0 [nouveau]
[21171.760393]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.761031]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21171.762309]  [<ffffffff816ac00f>] ? __mutex_unlock_slowpath+0x14f/0x190
[21171.762794]  [<ffffffff81050869>] ? __phys_addr+0x9/0x50
[21171.763690]  [<ffffffff81345fb8>] ? swiotlb_dma_mapping_error+0x18/0x30
[21171.764358]  [<ffffffff81499101>] ? usb_hcd_map_urb_for_dma+0x531/0x5b0
[21171.765536]  [<ffffffffa00c73d2>] ? nouveau_fbcon_fillrect+0xc2/0x110 [nouveau]
[21171.766134]  [<ffffffff8149922f>] ? usb_hcd_submit_urb+0xaf/0x860
[21171.766992]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.768393]  [<ffffffff816aec5e>] ? _raw_spin_unlock_irqrestore+0x7e/0x90
[21171.768864]  [<ffffffff814d336e>] ? usb_serial_generic_write_start+0x22e/0x270
[21171.769721]  [<ffffffff81090667>] ? kfifo_copy_in+0x77/0x90
[21171.771230]  [<ffffffff814d3664>] ? usb_serial_generic_write+0x84/0xd0
[21171.771902]  [<ffffffff814d4220>] ? usb_console_write+0x110/0x250
[21171.772388]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21171.773510]  [<ffffffff816af5b4>] ? retint_restore_args+0x13/0x13
[21171.774121]  [<ffffffff81066ed9>] ? vprintk+0x389/0x600
[21171.774964]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.776294]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.776891]  [<ffffffff810d375d>] ? trace_hardirqs_on+0xd/0x10
[21171.777601]  [<ffffffff816a1b67>] ? printk+0x51/0x53
[21171.779000]  [<ffffffff810de7b0>] ? __module_address+0x10/0x160
[21171.779666]  [<ffffffff816b301e>] ? sub_preempt_count+0xe/0xd0
[21171.780288]  [<ffffffff810e3145>] ? is_module_text_address+0x55/0x60
[21171.781622]  [<ffffffff8108c230>] ? __kernel_text_address+0x60/0x90
[21171.782202]  [<ffffffff8101e861>] ? print_context_stack+0x81/0x140
[21171.782763]  [<ffffffff8101d54f>] ? dump_trace+0x17f/0x2f0
[21171.784109]  [<ffffffff8101ea0c>] show_trace_log_lvl+0x5c/0x80
[21171.784571]  [<ffffffff8101ea45>] show_trace+0x15/0x20
[21171.785503]  [<ffffffff8106bbaf>] do_exit+0xb7f/0xb90
[21171.786201]  [<ffffffff8106bf0f>] do_group_exit+0x4f/0xc0
[21171.787277]  [<ffffffff8107eade>] get_signal_to_deliver+0x20e/0x880
[21171.787886]  [<ffffffff8107bdb0>] ? __send_signal+0x150/0x7f0
[21171.788749]  [<ffffffff811177de>] ? __rcu_read_unlock+0xe/0xa0
[21171.790075]  [<ffffffff8108b830>] ? task_tgid_nr_ns+0x20/0x20
[21171.790520]  [<ffffffff8101b315>] do_signal+0x65/0x5d0
[21171.791316]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21171.792624]  [<ffffffff8107f322>] ? set_current_blocked+0x52/0x60
[21171.793206]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21171.793784]  [<ffffffff816aebb1>] ? _raw_spin_unlock_irq+0x41/0x70
[21171.795181]  [<ffffffff8101b905>] do_notify_resume+0x65/0x80
[21171.795614]  [<ffffffff81335fae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[21171.796675]  [<ffffffff816b73a2>] int_signal+0x12/0x17

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Tue, 2012-04-17 at 23:15 -0400, Dave Jones wrote:

> That looks handy. Doesn't seem to work for me though on my test box.
> (config option is enabled.)
> 
> # echo 1 > /proc/sys/kernel/stack_tracer_enabled
> # cat /sys/kernel/debug/tracing/stack_trace
>         Depth    Size   Location    (-1 entries)
>         -----    ----   --------
> 
> That's all she wrote.

Hmm, was there any problems with the function tracer?
Messages in dmesg?

Just to make sure, what does

 /sys/kernel/debug/tracing/enabled_functions

have?

This would show what functions the stack tracer is using.

I just compiled the latest vanilla kernel and tried it out, and it
worked for me.

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Tue, Apr 17, 2012 at 11:43:31PM -0400, Steven Rostedt wrote:
 > On Tue, 2012-04-17 at 23:15 -0400, Dave Jones wrote:
 > 
 > > That looks handy. Doesn't seem to work for me though on my test box.
 > > (config option is enabled.)
 > > 
 > > # echo 1 > /proc/sys/kernel/stack_tracer_enabled
 > > # cat /sys/kernel/debug/tracing/stack_trace
 > >         Depth    Size   Location    (-1 entries)
 > >         -----    ----   --------
 > > 
 > > That's all she wrote.
 > 
 > Hmm, was there any problems with the function tracer?
 > Messages in dmesg?

nope.

 > Just to make sure, what does
 > 
 >  /sys/kernel/debug/tracing/enabled_functions
 > 
 > have?

33503 lines.
 
 > This would show what functions the stack tracer is using.
 > 
 > I just compiled the latest vanilla kernel and tried it out, and it
 > worked for me.

works on my other machines too with similar kernel configs, just not on the one I'm profiling.

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Tue, 2012-04-17 at 23:50 -0400, Dave Jones wrote:

>  > Just to make sure, what does
>  > 
>  >  /sys/kernel/debug/tracing/enabled_functions
>  > 
>  > have?
> 
> 33503 lines.

That sounds correct.

>  
>  > This would show what functions the stack tracer is using.
>  > 
>  > I just compiled the latest vanilla kernel and tried it out, and it
>  > worked for me.
> 
> works on my other machines too with similar kernel configs, just not on the one I'm profiling.

I have to ask. Is this a x86 box?

Also, have you tested to see if function tracing works?

# cd /sys/kernel/debug/tracing
# echo function > current_tracer
# cat trace

If function tracing doesn't work this wouldn't either.

I'm also assuming you have CONFIG_STACKTRACE and
CONFIG_STACKTRACE_SUPPORT enabled. They should be selected, but configs
can always get screwed up.

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Tue, 2012-04-17 at 23:57 -0400, Steven Rostedt wrote:

> Also, have you tested to see if function tracing works?
> 
> # cd /sys/kernel/debug/tracing
> # echo function > current_tracer
> # cat trace

Also make sure that the max is zero:

# cat stack_max_size
# echo 0 > stack_max_size

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Tue, Apr 17, 2012 at 11:57:21PM -0400, Steven Rostedt wrote:
 
 > >  > This would show what functions the stack tracer is using.
 > >  > 
 > >  > I just compiled the latest vanilla kernel and tried it out, and it
 > >  > worked for me.
 > > 
 > > works on my other machines too with similar kernel configs, just not on the one I'm profiling.
 > 
 > I have to ask. Is this a x86 box?

yeah, 64-bit Xeon circa 2008.
 
 > Also, have you tested to see if function tracing works?
 > 
 > # cd /sys/kernel/debug/tracing
 > # echo function > current_tracer
 > # cat trace
 > 
 > If function tracing doesn't work this wouldn't either.

That just prints out..

# tracer: function
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |

 > I'm also assuming you have CONFIG_STACKTRACE and
 > CONFIG_STACKTRACE_SUPPORT enabled. They should be selected, but configs
 > can always get screwed up.

CONFIG_STACKTRACE_SUPPORT=y
CONFIG_STACKTRACE=y

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, Apr 18, 2012 at 12:00:44AM -0400, Steven Rostedt wrote:
 > On Tue, 2012-04-17 at 23:57 -0400, Steven Rostedt wrote:
 > 
 > > Also, have you tested to see if function tracing works?
 > > 
 > > # cd /sys/kernel/debug/tracing
 > > # echo function > current_tracer
 > > # cat trace
 > 
 > Also make sure that the max is zero:
 > 
 > # cat stack_max_size
 > # echo 0 > stack_max_size

Yep, it is zero.

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-04-18 at 00:06 -0400, Dave Jones wrote:

> That just prints out..
> 
> # tracer: function
> #
> # entries-in-buffer/entries-written: 0/0   #P:4
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
> 
>  > I'm also assuming you have CONFIG_STACKTRACE and
>  > CONFIG_STACKTRACE_SUPPORT enabled. They should be selected, but configs
>  > can always get screwed up.
> 
> CONFIG_STACKTRACE_SUPPORT=y
> CONFIG_STACKTRACE=y
> 

OK, function tracing is broken on your box. Could you send me your full
config and I'll take a look at it tomorrow. Bed time for me now ;-)

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, Apr 18, 2012 at 12:09:24AM -0400, Steven Rostedt wrote:
 > On Wed, 2012-04-18 at 00:06 -0400, Dave Jones wrote:
 > 
 > > That just prints out..
 > > 
 > > # tracer: function
 > > #
 > > # entries-in-buffer/entries-written: 0/0   #P:4
 > > #
 > > #                              _-----=> irqs-off
 > > #                             / _----=> need-resched
 > > #                            | / _---=> hardirq/softirq
 > > #                            || / _--=> preempt-depth
 > > #                            ||| /     delay
 > > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 > > #              | |       |   ||||       |         |
 > > 
 > >  > I'm also assuming you have CONFIG_STACKTRACE and
 > >  > CONFIG_STACKTRACE_SUPPORT enabled. They should be selected, but configs
 > >  > can always get screwed up.
 > > 
 > > CONFIG_STACKTRACE_SUPPORT=y
 > > CONFIG_STACKTRACE=y
 > > 
 > 
 > OK, function tracing is broken on your box. Could you send me your full
 > config and I'll take a look at it tomorrow. Bed time for me now ;-)

http://fpaste.org/b8PN/raw/

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:

>  > OK, function tracing is broken on your box. Could you send me your full
>  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
> 
> http://fpaste.org/b8PN/raw/

Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
compiling for that box now.

Could you also paste your full dmesg.

Thanks,

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, Apr 18, 2012 at 10:56:05AM -0400, Steven Rostedt wrote:
 > On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:
 > 
 > >  > OK, function tracing is broken on your box. Could you send me your full
 > >  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
 > > 
 > > http://fpaste.org/b8PN/raw/
 > 
 > Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
 > compiling for that box now.
 > 
 > Could you also paste your full dmesg.

http://fpaste.org/QFmg/

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, Apr 18, 2012 at 10:56:05AM -0400, Steven Rostedt wrote:
 > On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:
 > 
 > >  > OK, function tracing is broken on your box. Could you send me your full
 > >  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
 > > 
 > > http://fpaste.org/b8PN/raw/
 > 
 > Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
 > compiling for that box now.
 > 
 > Could you also paste your full dmesg.

Oh, I guess it's this..

"PEBS disabled due to CPU errata."

Crap. Never even noticed that before.

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-04-18 at 10:56 -0400, Steven Rostedt wrote:
> On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:
> 
> >  > OK, function tracing is broken on your box. Could you send me your full
> >  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
> > 
> > http://fpaste.org/b8PN/raw/
> 
> Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
> compiling for that box now.

I ran your config on my own Xeon, and it worked just fine.

> 
> Could you also paste your full dmesg.

I guess I need to examine what happens during boot up that may cause
this issue for you :-/

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-04-18 at 11:30 -0400, Dave Jones wrote:
> On Wed, Apr 18, 2012 at 10:56:05AM -0400, Steven Rostedt wrote:
>  > On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:
>  > 
>  > >  > OK, function tracing is broken on your box. Could you send me your full
>  > >  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
>  > > 
>  > > http://fpaste.org/b8PN/raw/
>  > 
>  > Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
>  > compiling for that box now.
>  > 
>  > Could you also paste your full dmesg.
> 
> Oh, I guess it's this..
> 
> "PEBS disabled due to CPU errata."
> 
> Crap. Never even noticed that before.

Yeah, but that shouldn't stop the function tracer from working.

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Linus Torvalds]

On Tue, Apr 17, 2012 at 8:19 PM, Dave Jones <davej@redhat.com> wrote:
>
> So now that I'm instrumenting it, it's taking a lot longer to trigger
> (how typical). Almost 6 hours in though, it's down to 72 bytes, and spewed
> the traces below, which look pretty.. deep.

Yeah. Sadly, they are less useful than I was hoping for. It's not some
single deep call-chain, it's almost all debug stuff and the "did we
release the RCU lock" or preemption checks, which I guess makes sense.
You have tons of options enabled in your kernel that makes for deeper
stack traces, and then all the interesting stuff gets overwritten by
what happened later.

For example, it looks like you have the USB serial console enabled,
and some of those deep stack traces are about that - and largely got
overwritten by the "dump_trace()" logic itself. So dump_trace()
printing stuff out also ended up overwriting the stack trace that we
were interested in.

I assume you have USB serial console on for a reason (ie: great for
catching oopses before the machine dies), but in this case it hurts.

Could you try just adding a

   console_lock();
   ...
   console_unlock();

around the show_trace() call. That will force the code to not actually
call down to the console layer until after the console_unlock(), so
the printing of the stack trace won't affect the stack *too* much.

That said, if you get the function tracer thing working, that will
give much nicer backtraces.

                   Linus

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, Apr 18, 2012 at 10:02:06AM -0700, Linus Torvalds wrote:

 > > the traces below, which look pretty.. deep.
 > 
 > Yeah. Sadly, they are less useful than I was hoping for. It's not some
 > single deep call-chain, it's almost all debug stuff and the "did we
 > release the RCU lock" or preemption checks, which I guess makes sense.
 > You have tons of options enabled in your kernel that makes for deeper
 > stack traces, and then all the interesting stuff gets overwritten by
 > what happened later.

One thing I'm curious about.. Some of the function names are repeated
for a reason that doesn't seem obvious to me, when the call chain doesn't
call them in a loop. What's that about ?

 > I assume you have USB serial console on for a reason (ie: great for
 > catching oopses before the machine dies), but in this case it hurts.

Yeah, there's a (possibly related) problem where once a day some oops
gets triggered that just wedges the machine. I've not managed to capture
it yet, and the most I've gotten over the usb console was about
a dozen characters before it hung.

I've disabled the console blanking, and hooked up a monitor to it.
Perhaps that'll be enough to capture it without resorting to usb console.

 > Could you try just adding a
 > 
 >    console_lock();
 >    ...
 >    console_unlock();
 > 
 > around the show_trace() call. That will force the code to not actually
 > call down to the console layer until after the console_unlock(), so
 > the printing of the stack trace won't affect the stack *too* much.

That's a neat trick. I'll add that, in case I do have to fall back to usb console.

thanks,

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Linus Torvalds]

On Wed, Apr 18, 2012 at 10:14 AM, Dave Jones <davej@redhat.com> wrote:
>
> One thing I'm curious about.. Some of the function names are repeated
> for a reason that doesn't seem obvious to me, when the call chain doesn't
> call them in a loop. What's that about ?

In a "real" stack trace, it's usually due to a pointer to a function
that just gets passed around as an argument.

However, in this case, I think it's simply because you are seeing a
lot of stack-traces "on top of each other", where the callers had
slightly different stack offsets, but old stack traces "shine through"
because the stack of the newer trace is not very dense.

Gcc often generates very sparse stack frames. Sometimes it is because
of stack alignment issues, but more often it's because gcc generates
the frame for all possible local variables, and then we took an early
exit from the function (or are still in the middle of the call chain)
and part of the stack simply hasn't been modified at all.

And sometimes it is because gcc stack space allocation simply sucks.
There was a time when gcc would never share stack space between local
variables even when they had no overlap in lifetime. I know they fixed
*some* of those cases, but I suspect it's still true that gcc just
often allocates way more stack than it really needs, and then you see
old stale stack contents shine through.

                         Linus

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-04-18 at 12:43 -0400, Steven Rostedt wrote:
> On Wed, 2012-04-18 at 11:30 -0400, Dave Jones wrote:
> > On Wed, Apr 18, 2012 at 10:56:05AM -0400, Steven Rostedt wrote:
> >  > On Wed, 2012-04-18 at 09:58 -0400, Dave Jones wrote:
> >  > 
> >  > >  > OK, function tracing is broken on your box. Could you send me your full
> >  > >  > config and I'll take a look at it tomorrow. Bed time for me now ;-)
> >  > > 
> >  > > http://fpaste.org/b8PN/raw/
> >  > 
> >  > Hmm, I had no problems with this config. But that wasn't on my Xeon. I'm
> >  > compiling for that box now.
> >  > 
> >  > Could you also paste your full dmesg.
> > 
> > Oh, I guess it's this..
> > 
> > "PEBS disabled due to CPU errata."
> > 
> > Crap. Never even noticed that before.
> 
> Yeah, but that shouldn't stop the function tracer from working.
> 

Hi Dave,

Have we ever figured out why this wasn't working? Did it start working
on newer kernels?

-- Steve

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Dave Jones]

On Wed, May 23, 2012 at 10:37:08AM -0400, Steven Rostedt wrote:

 > > > Oh, I guess it's this..
 > > > 
 > > > "PEBS disabled due to CPU errata."
 > > > 
 > > > Crap. Never even noticed that before.
 > > 
 > > Yeah, but that shouldn't stop the function tracer from working.
 > 
 > Hi Dave,
 > 
 > Have we ever figured out why this wasn't working? Did it start working
 > on newer kernels?

I think that was where we left it.

But! Linus' current tree seems to have working tracing on that box.
Don't break it again! ;-)

	Dave

Re: [3.4-rc3] Thread overran stack, or stack corrupted

[Steven Rostedt]

On Wed, 2012-05-23 at 11:05 -0400, Dave Jones wrote:

> But! Linus' current tree seems to have working tracing on that box.
> Don't break it again! ;-)

You could install ktest and run a reverse bisect to find out what fixed
it ;-)

-- Steve