Bug 13386 - BUG: using smp_processor_id() in preemptible code
Summary: BUG: using smp_processor_id() in preemptible code
Status: RESOLVED FIXED
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-11-05 13:35 UTC by Mark Wielaard
Modified: 2011-11-07 23:41 UTC (History)
0 users

See Also:
Host:
Target:
Build:
Last reconfirmed:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Mark Wielaard 2011-11-05 13:35:17 UTC 
Found this in my logs:

Nov  5 13:56:49 armando kernel: [ 1353.700391] BUG: using smp_processor_id() in preemptible [00000000] code: stapio/20061
Nov  5 13:56:49 armando kernel: [ 1353.700523] caller is _stp_cleanup_and_exit+0x240/0x2c8 [stap_08fb73e8603c2f873ec67447b857d69_20061]
Nov  5 13:56:49 armando kernel: [ 1353.700565] Backtrace:
Nov  5 13:56:49 armando kernel: [ 1353.700677] [<c00428d0>] (unwind_backtrace+0x0/0xe0) from [<c023e610>] (debug_smp_processor_id+0xbc/0xf0)
Nov  5 13:56:49 armando kernel: [ 1353.700808] [<c023e610>] (debug_smp_processor_id+0xbc/0xf0) from [<bf3cb8d4>] (_stp_cleanup_and_exit+0x240/0x2c8 [stap_08fb73e8603c2f873ec67447b857d69_20061])
Nov  5 13:56:49 armando kernel: [ 1353.701024] [<bf3cb8d4>] (_stp_cleanup_and_exit+0x240/0x2c8 [stap_08fb73e8603c2f873ec67447b857d69_20061]) from [<bf3cbf84>] (_stp_ctl_write_cmd+0x628/0x950 [stap_08fb73e8603c2f873ec67447b857d69_20061])
Nov  5 13:56:49 armando kernel: [ 1353.701179] [<bf3cbf84>] (_stp_ctl_write_cmd+0x628/0x950 [stap_08fb73e8603c2f873ec67447b857d69_20061]) from [<c01139c8>] (vfs_write+0xb0/0x178)
Nov  5 13:56:49 armando kernel: [ 1353.701267] [<c01139c8>] (vfs_write+0xb0/0x178) from [<c0113ca8>] (sys_write+0x3c/0x68)
Nov  5 13:56:49 armando kernel: [ 1353.701359] [<c0113ca8>] (sys_write+0x3c/0x68) from [<c003b760>] (ret_fast_syscall+0x0/0x30)

I don't immediately see where in _stp_cleanup_and_exit() we would use smp_processor_id(), but if we do, then that would probably be a bug if we could be preempted, which it seems we can here.
Comment 1 Mark Wielaard 2011-11-06 21:47:43 UTC 
Found two more, one in _stp_vsnprintf and another in _stp_reserve_bytes:

Nov  6 00:04:57 armando kernel: [19775.710420] BUG: using smp_processor_id() in preemptible [00000000] code: stapio/3646
Nov  6 00:04:57 armando kernel: [19775.717338] caller is _stp_vsnprintf+0x5b8/0x1048 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646]
Nov  6 00:04:57 armando kernel: [19775.717379] Backtrace:
Nov  6 00:04:57 armando kernel: [19775.717489] [<c00428d0>] (unwind_backtrace+0x0/0xe0) from [<c023e610>] (debug_smp_processor_id+0xbc/0xf0)
Nov  6 00:04:57 armando kernel: [19775.717604] [<c023e610>] (debug_smp_processor_id+0xbc/0xf0) from [<bf19adac>] 
(_stp_vsnprintf+0x5b8/0x1048 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646])
Nov  6 00:04:57 armando kernel: [19775.717785] [<bf19adac>] (_stp_vsnprintf+0x5b8/0x1048 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646]) from [<bf19b880>] (_stp_printf+0x20/0x2c [stap_2b091f3dbad1f4bb58af3d26c710df1_3646])
Nov  6 00:04:57 armando kernel: [19775.717931] [<bf19b880>] (_stp_printf+0x20/0x2c [stap_2b091f3dbad1f4bb58af3d26c710df1_3646]) from [<bf19bec0>] (_stp_cleanup_and_exit+0x19c/0x9e0 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646])
Nov  6 00:04:57 armando kernel: [19775.718078] [<bf19bec0>] (_stp_cleanup_and_exit+0x19c/0x9e0 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646]) from [<bf19cab4>] (_stp_ctl_write_cmd+0x3b0/0x674 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646])
Nov  6 00:04:57 armando kernel: [19775.718214] [<bf19cab4>] (_stp_ctl_write_cmd+0x3b0/0x674 [stap_2b091f3dbad1f4bb58af3d26c710df1_3646]) from [<c01139c8>] (vfs_write+0xb0/0x178)
Nov  6 00:04:57 armando kernel: [19775.718303] [<c01139c8>] (vfs_write+0xb0/0x178) from [<c0113ca8>] (sys_write+0x3c/0x68)
Nov  6 00:04:57 armando kernel: [19775.718394] [<c0113ca8> (sys_write+0x3c/0x68) from [<c003b760>] (ret_fast_syscall+0x0/0x30)


Nov  6 00:04:32 armando kernel: [19750.838018] BUG: using smp_processor_id() in preemptible [00000000] code: stapio/3610
Nov  6 00:04:32 armando kernel: [19750.844055] caller is _stp_reserve_bytes+0x18/0x84 [stap_dba48f0e091451400655598b741caa3a_2_3610]
Nov  6 00:04:32 armando kernel: [19750.844100] Backtrace:
Nov  6 00:04:32 armando kernel: [19750.844191] [<c00428d0>] (unwind_backtrace+0x0/0xe0) from [<c023e610>] (debug_smp_processor_id+0xbc/0xf0)
Nov  6 00:04:32 armando kernel: [19750.844315] [<c023e610>] (debug_smp_processor_id+0xbc/0xf0) from [<bf17c2cc>] 
(_stp_reserve_bytes+0x18/0x84 [stap_dba48f0e091451400655598b741caa3a_2_3610])
Nov  6 00:04:32 armando kernel: [19750.844485] [<bf17c2cc>] (_stp_reserve_bytes+0x18/0x84 [stap_dba48f0e091451400655598b741caa3a_2_3610]) from [<bf17c8f8>] (_stp_vsnprintf+0x448/0x9f4 [stap_dba48f0e091451400655598b741caa3a_2_3610])
Nov  6 00:04:32 armando kernel: [19750.844654] [<bf17c8f8>] (_stp_vsnprintf+0x448/0x9f4 [stap_dba48f0e091451400655598b741caa3a_2_3610]) from [<bf17cee8>] (_stp_printf+0x20/0x2c [stap_dba48f0e091451400655598b741caa3a_2_3610])
Nov  6 00:04:32 armando kernel: [19750.844832] [<bf17cee8>] (_stp_printf+0x20/0x2c [stap_dba48f0e091451400655598b741caa3a_2_3610]) from [<bf17e198>] (_stp_cleanup_and_exit+0x280/0x448 [stap_dba48f0e091451400655598b741caa3a_2_3610])
Nov  6 00:04:32 armando kernel: [19750.845011] [<bf17e198>] (_stp_cleanup_and_exit+0x280/0x448 [stap_dba48f0e0914
51400655598b741caa3a_2_3610]) from [<bf17e7d0>] (_stp_ctl_write_cmd+0x470/0x778 [stap_dba48f0e091451400655598b741caa3a_2_3610])
Nov  6 00:04:32 armando kernel: [19750.845159] [<bf17e7d0>] (_stp_ctl_write_cmd+0x470/0x778 [stap_dba48f0e091451400655598b741caa3a_2_3610]) from [<c01139c8>] (vfs_write+0xb0/0x178)
Nov  6 00:04:32 armando kernel: [19750.845250] [<c01139c8>] (vfs_write+0xb0/0x178) from [<c0113ca8>] (sys_write+0x3c/0x68)
Nov  6 00:04:32 armando kernel: [19750.845336] [<c0113ca8>] (sys_write+0x3c/0x68) from [<c003b760>] (ret_fast_syscall+0x0/0x30)


These do seem dangerous in case the code is preempted shortly after the usage of smp_processor_id() is called. Are we sure we cannot be preempted in these cases?
Comment 2 Mark Wielaard 2011-11-07 23:41:11 UTC 
commit c114ce7ffcb39e37f6468be80ffa3fa1f18bcf0e
Author: Frank Ch. Eigler <fche@redhat.com>
Date:   Mon Nov 7 14:19:05 2011 -0500

    PR13386: disable preemption around printing-happy parts of *module_exit().

    * translate.cxx (c_unparser::emit_module_exit): Since we use stp_printf
      (that internally is preempt-sensitive), we need to disable preemption
      (or at least cpu switching) during this stage.