Thread overran stack, or stack corrupted

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

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

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

thanks,

Dave

@@ -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();
 
 	/*

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

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

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

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

nope.

33503 lines.

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

Dave

That sounds correct.

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

Also make sure that the max is zero:

# cat stack_max_size
# echo 0 > stack_max_size

-- Steve

Yep, it is zero.

Dave

yeah, 64-bit Xeon circa 2008.

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
#              | |       |   ||||       |         |

CONFIG_STACKTRACE_SUPPORT=y
CONFIG_STACKTRACE=y

Dave

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

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

Dave

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

http://fpaste.org/QFmg/

Dave

Oh, I guess it's this..

"PEBS disabled due to CPU errata."

Crap. Never even noticed that before.

Dave

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

-- Steve

Hi Dave,

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

-- Steve

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

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

-- Steve

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

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

-- Steve

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

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

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 ?

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.

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

thanks,

Dave

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