buggy stap print rewrite

0-deadlock.txt

[  138.841539] stap_79e089a8f5becc466d80561a9e95aaf3_9596 (tracepoints2.stp): systemtap: 4.4/0.177, base: ffffffffc067b000, memory: 232data/32text/29ctx/2150net/135alloc kb, probes: 2
[  138.842290] 
[  138.842300] ======================================================
[  138.842312] [ INFO: possible circular locking dependency detected ]
[  138.842325] 3.10.0-1127.19.1.el7.x86_64.debug #1 Tainted: G           OE  ------------  
[  138.842339] -------------------------------------------------------
[  138.842351] stapio/9596 is trying to acquire lock:
[  138.842361]  (&(&pool->lock)->rlock){-.-...}, at: [<ffffffff810d986d>] __queue_work+0x23d/0x5c0
[  138.842386] 
               but task is already holding lock:
[  138.842397]  (&rq->lock){-.-.-.}, at: [<ffffffff81885947>] __schedule+0xe7/0x810
[  138.842417] 
               which lock already depends on the new lock.
               
[  138.842433] 
               the existing dependency chain (in reverse order) is:
[  138.842446] 
               -> #2 (&rq->lock){-.-.-.}:
[  138.842461]        [<ffffffff81146039>] lock_acquire+0x99/0x1e0
[  138.842475]        [<ffffffff81889226>] _raw_spin_lock+0x46/0x80
[  138.842489]        [<ffffffff81102063>] sched_move_task+0x53/0x2c0
[  138.842505]        [<ffffffff811022fe>] cpu_cgroup_fork+0xe/0x10
[  138.842517]        [<ffffffff81167840>] cgroup_post_fork+0x50/0xe0
[  138.842534]        [<ffffffff810ad501>] copy_process+0x1811/0x1e50
[  138.842548]        [<ffffffff810adcd1>] do_fork+0x81/0x760
[  138.842561]        [<ffffffff810ae3d6>] kernel_thread+0x26/0x30
[  138.842575]        [<ffffffff81869803>] rest_init+0x23/0x150
[  138.842589]        [<ffffffff81fec25f>] start_kernel+0x487/0x4a8
[  138.842604]        [<ffffffff81feb78c>] x86_64_start_reservations+0x24/0x26
[  138.842620]        [<ffffffff81feb8e2>] x86_64_start_kernel+0x154/0x177
[  138.842635]        [<ffffffff810000d5>] start_cpu+0x5/0x14
[  138.842649] 
               -> #1 (&p->pi_lock){-.-.-.}:
[  138.842664]        [<ffffffff81146039>] lock_acquire+0x99/0x1e0
[  138.842679]        [<ffffffff81889dde>] _raw_spin_lock_irqsave+0x5e/0xa0
[  138.842695]        [<ffffffff810fec90>] try_to_wake_up+0x30/0x490
[  138.842709]        [<ffffffff810ff105>] wake_up_process+0x15/0x20
[  138.842724]        [<ffffffff810d6ac7>] start_worker+0x27/0x30
[  138.842737]        [<ffffffff810d7c92>] create_and_start_worker+0x42/0x80
[  138.842753]        [<ffffffff82017f7e>] workqueue_init+0x65/0xcf
[  138.842767]        [<ffffffff81fec3c6>] kernel_init_freeable+0x146/0x2a2
[  138.842782]        [<ffffffff8186993e>] kernel_init+0xe/0xf0
[  138.842796]        [<ffffffff818958dd>] ret_from_fork_nospec_begin+0x7/0x21
[  138.842813] 
               -> #0 (&(&pool->lock)->rlock){-.-...}:
[  138.843155]        [<ffffffff81144fe1>] __lock_acquire+0xec1/0x1630
[  138.843496]        [<ffffffff81146039>] lock_acquire+0x99/0x1e0
[  138.843828]        [<ffffffff81889226>] _raw_spin_lock+0x46/0x80
[  138.844164]        [<ffffffff810d986d>] __queue_work+0x23d/0x5c0
[  138.844500]        [<ffffffff810d9c86>] queue_work_on+0x96/0xa0
[  138.844825]        [<ffffffffc068081b>] probe_6333+0x2fb/0x330 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.845228]        [<ffffffffc0682c1b>] enter_real_tracepoint_probe_0+0x1bb/0x3d5 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.845892]        [<ffffffffc067b00e>] enter_tracepoint_probe_0+0xe/0x10 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.846247]        [<ffffffff81885d03>] __schedule+0x4a3/0x810
[  138.846605]        [<ffffffff81886099>] schedule+0x29/0x70
[  138.846944]        [<ffffffff818851be>] schedule_hrtimeout_range_clock+0xce/0x190
[  138.847283]        [<ffffffff81885293>] schedule_hrtimeout_range+0x13/0x20
[  138.847595]        [<ffffffff812c7425>] poll_schedule_timeout+0x55/0xe0
[  138.847941]        [<ffffffff812c8141>] do_select+0x841/0x990
[  138.848288]        [<ffffffff812c8567>] core_sys_select+0x2d7/0x550
[  138.848618]        [<ffffffff812c8bd1>] SyS_pselect6+0x2b1/0x2d0
[  138.848952]        [<ffffffff81895a92>] system_call_fastpath+0x25/0x2a
[  138.849298] 
               other info that might help us debug this:
               
[  138.850184] Chain exists of:
                 &(&pool->lock)->rlock --> &p->pi_lock --> &rq->lock
               
[  138.850945]  Possible unsafe locking scenario:
               
[  138.851401]        CPU0                    CPU1
[  138.851672]        ----                    ----
[  138.851985]   lock(&rq->lock);
[  138.852308]                                lock(&p->pi_lock);
[  138.852622]                                lock(&rq->lock);
[  138.852910]   lock(&(&pool->lock)->rlock);
[  138.853097] 
                *** DEADLOCK ***
               
[  138.853751] 2 locks held by stapio/9596:
[  138.853943]  #0:  (&rq->lock){-.-.-.}, at: [<ffffffff81885947>] __schedule+0xe7/0x810
[  138.854189]  #1:  (_stp_log_flush_lock){......}, at: [<ffffffffc06806f4>] probe_6333+0x1d4/0x330 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.854729] 
               stack backtrace:
[  138.855236] CPU: 7 PID: 9596 Comm: stapio Kdump: loaded Tainted: G           OE  ------------   3.10.0-1127.19.1.el7.x86_64.debug #1
[  138.856127] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20180531_142017-buildhw-08.phx2.fedoraproject.org-1.fc28 04/01/2014
[  138.856836] Call Trace:
[  138.857195]  [<ffffffff8187e46b>] dump_stack+0x19/0x1b
[  138.857558]  [<ffffffff818772d4>] print_circular_bug+0x1f9/0x207
[  138.857914]  [<ffffffff811436d7>] check_prevs_add+0x957/0x960
[  138.858274]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.858624]  [<ffffffff81144fe1>] __lock_acquire+0xec1/0x1630
[  138.858980]  [<ffffffff8107a819>] ? kvm_sched_clock_read+0x9/0x20
[  138.859347]  [<ffffffff8103eb89>] ? sched_clock+0x9/0x10
[  138.859705]  [<ffffffff81146039>] lock_acquire+0x99/0x1e0
[  138.860051]  [<ffffffff810d986d>] ? __queue_work+0x23d/0x5c0
[  138.860402]  [<ffffffff81889226>] _raw_spin_lock+0x46/0x80
[  138.860735]  [<ffffffff810d986d>] ? __queue_work+0x23d/0x5c0
[  138.861053]  [<ffffffff810d986d>] __queue_work+0x23d/0x5c0
[  138.861383]  [<ffffffff810d9c86>] queue_work_on+0x96/0xa0
[  138.861710]  [<ffffffffc068081b>] probe_6333+0x2fb/0x330 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.862061]  [<ffffffffc0682c1b>] enter_real_tracepoint_probe_0+0x1bb/0x3d5 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.862424]  [<ffffffffc067b00e>] enter_tracepoint_probe_0+0xe/0x10 [stap_79e089a8f5becc466d80561a9e95aaf3_9596]
[  138.862778]  [<ffffffff81885d03>] __schedule+0x4a3/0x810
[  138.863144]  [<ffffffff81886099>] schedule+0x29/0x70
[  138.863504]  [<ffffffff818851be>] schedule_hrtimeout_range_clock+0xce/0x190
[  138.863865]  [<ffffffff810e88a0>] ? hrtimer_get_res+0x50/0x50
[  138.864218]  [<ffffffff818851b2>] ? schedule_hrtimeout_range_clock+0xc2/0x190
[  138.864578]  [<ffffffff81885293>] schedule_hrtimeout_range+0x13/0x20
[  138.864952]  [<ffffffff812c7425>] poll_schedule_timeout+0x55/0xe0
[  138.865335]  [<ffffffff812c8141>] do_select+0x841/0x990
[  138.865683]  [<ffffffff812c7905>] ? do_select+0x5/0x990
[  138.866011]  [<ffffffff812c7340>] ? __pollwait+0xf0/0xf0
[  138.866322]  [<ffffffff81150ca3>] ? __module_address+0x73/0xd0
[  138.866625]  [<ffffffff8107daad>] ? update_stack_state+0x7d/0xe0
[  138.866955]  [<ffffffff8107dbdc>] ? unwind_next_frame.part.5+0x8c/0xd0
[  138.867323]  [<ffffffff8107dc36>] ? unwind_next_frame+0x16/0x20
[  138.867683]  [<ffffffff81046e8b>] ? __save_stack_trace+0x8b/0x100
[  138.868038]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.868395]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.868749]  [<ffffffff8107a819>] ? kvm_sched_clock_read+0x9/0x20
[  138.869114]  [<ffffffff8103eb89>] ? sched_clock+0x9/0x10
[  138.869469]  [<ffffffff81103085>] ? local_clock+0x25/0x30
[  138.869798]  [<ffffffff8114036f>] ? lock_release_holdtime.part.30+0xf/0x1a0
[  138.870166]  [<ffffffff81146488>] ? lock_release_non_nested+0x308/0x360
[  138.870521]  [<ffffffff812415d1>] ? __might_fault+0x51/0xb0
[  138.870858]  [<ffffffff812c8567>] core_sys_select+0x2d7/0x550
[  138.871179]  [<ffffffff812c82d7>] ? core_sys_select+0x47/0x550
[  138.871466]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.871760]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.872042]  [<ffffffff8107a819>] ? kvm_sched_clock_read+0x9/0x20
[  138.872332]  [<ffffffff8103eb89>] ? sched_clock+0x9/0x10
[  138.872608]  [<ffffffff811336b6>] ? ktime_get_ts64+0x86/0x190
[  138.872879]  [<ffffffff8107a7f3>] ? kvm_clock_read+0x33/0x40
[  138.873038]  [<ffffffff8107a809>] ? kvm_clock_get_cycles+0x9/0x10
[  138.873223]  [<ffffffff811336ee>] ? ktime_get_ts64+0xbe/0x190
[  138.873380]  [<ffffffff812c78cc>] ? poll_select_set_timeout+0x5c/0x90
[  138.873546]  [<ffffffff812c8bd1>] SyS_pselect6+0x2b1/0x2d0
[  138.873707]  [<ffffffff81895a92>] system_call_fastpath+0x25/0x2a
[  164.548529] NMI watchdog: BUG: soft lockup - CPU#5 stuck for 23s! [cc1:6923]
[  164.548711] Modules linked in: stap_79e089a8f5becc466d80561a9e95aaf3_9596(OE) ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat iptable_mangle iptable_security iptable_raw nf_conntrack ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ppdev iosf_mbi kvm_intel kvm irqbypass crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd joydev virtio_balloon pcspkr sg parport_pc parport i2c_piix4 ip_tables xfs libcrc32c sr_mod cdrom sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi virtio_console
[  164.549897]  virtio_net virtio_scsi net_failover failover cirrus drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm ata_piix crct10dif_pclmul drm crct10dif_common crc32c_intel libata serio_raw virtio_pci virtio_ring virtio drm_panel_orientation_quirks floppy dm_mirror dm_region_hash dm_log dm_mod [last unloaded: stap_f1632b7fb2fb0c0fc0d6eafda99ecf58__9418]
[  164.550769] irq event stamp: 6995349
[  164.550985] hardirqs last  enabled at (6995349): [<ffffffff81895ac2>] sysret_check+0x26/0x10d
[  164.551203] hardirqs last disabled at (6995348): [<ffffffff81895aae>] sysret_check+0x12/0x10d
[  164.551416] softirqs last  enabled at (6994898): [<ffffffff810bac14>] __do_softirq+0x1a4/0x470
[  164.551636] softirqs last disabled at (6994893): [<ffffffff8189923c>] call_softirq+0x1c/0x30
[  164.551849] CPU: 5 PID: 6923 Comm: cc1 Kdump: loaded Tainted: G           OE  ------------   3.10.0-1127.19.1.el7.x86_64.debug #1
[  164.552281] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20180531_142017-buildhw-08.phx2.fedoraproject.org-1.fc28 04/01/2014
[  164.552740] task: ffff8801721ac000 ti: ffff88017239c000 task.ti: ffff88017239c000
[  164.552987] RIP: 0010:[<ffffffff8114e322>]  [<ffffffff8114e322>] generic_exec_single+0x102/0x200
[  164.553230] RSP: 0018:ffff88017239fc00  EFLAGS: 00000202
[  164.553469] RAX: 0000000000000010 RBX: ffffffff8188b543 RCX: 0000000000000030
[  164.553725] RDX: 0000000000000010 RSI: 0000000000000010 RDI: 0000000000000286
[  164.553979] RBP: ffff88017239fc60 R08: ffffffff818b3ec0 R09: 0000000000000000
[  164.554224] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff8119a597
[  164.554470] R13: ffff88017239fb78 R14: ffff8801721ac000 R15: ffff88017239c000
[  164.554726] FS:  00007f0c3fa0a840(0000) GS:ffff880179000000(0000) knlGS:0000000000000000
[  164.554985] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  164.555239] CR2: 00007f0c3f9e9000 CR3: 000000017086e000 CR4: 0000000000360fe0
[  164.555500] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  164.555765] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  164.556027] Call Trace:
[  164.556284]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  164.556550]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  164.556807]  [<ffffffff8114e4e0>] smp_call_function_single+0x80/0xe0
[  164.557070]  [<ffffffff81413e3d>] ? cpumask_next_and+0x4d/0xb0
[  164.557331]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  164.557597]  [<ffffffff8114eb41>] smp_call_function_many+0x2c1/0x320
[  164.557860]  [<ffffffff8108d3a8>] native_flush_tlb_others+0xb8/0xc0
[  164.558133]  [<ffffffff8108d42b>] flush_tlb_mm_range+0x7b/0x160
[  164.558397]  [<ffffffff812414b6>] tlb_flush_mmu_tlbonly+0xa6/0xc0
[  164.558667]  [<ffffffff8124337f>] arch_tlb_finish_mmu+0x3f/0x80
[  164.558935]  [<ffffffff812434a3>] tlb_finish_mmu+0x23/0x30
[  164.559198]  [<ffffffff8124d1c4>] unmap_region+0xf4/0x140
[  164.559460]  [<ffffffff8124d7d1>] ? __vma_rb_erase+0x121/0x220
[  164.559728]  [<ffffffff8124fa05>] do_munmap+0x2a5/0x480
[  164.559990]  [<ffffffff8124fc48>] vm_munmap+0x68/0xb0
[  164.560242]  [<ffffffff81250f42>] SyS_munmap+0x22/0x30
[  164.560488]  [<ffffffff81895a92>] system_call_fastpath+0x25/0x2a
[  164.560739] Code: 89 de 48 03 14 c5 a0 08 df 81 48 89 df e8 27 e0 2d 00 84 c0 75 53 45 85 ed 74 16 f6 43 20 01 74 10 0f 1f 84 00 00 00 00 00 f3 90 <f6> 43 20 01 75 f8 31 c0 48 8b 7c 24 38 65 48 33 3c 25 28 00 00 
[  192.548530] NMI watchdog: BUG: soft lockup - CPU#5 stuck for 23s! [cc1:6923]
[  192.548794] Modules linked in: stap_79e089a8f5becc466d80561a9e95aaf3_9596(OE) ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat iptable_mangle iptable_security iptable_raw nf_conntrack ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ppdev iosf_mbi kvm_intel kvm irqbypass crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd joydev virtio_balloon pcspkr sg parport_pc parport i2c_piix4 ip_tables xfs libcrc32c sr_mod cdrom sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi virtio_console
[  192.550344]  virtio_net virtio_scsi net_failover failover cirrus drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm ata_piix crct10dif_pclmul drm crct10dif_common crc32c_intel libata serio_raw virtio_pci virtio_ring virtio drm_panel_orientation_quirks floppy dm_mirror dm_region_hash dm_log dm_mod [last unloaded: stap_f1632b7fb2fb0c0fc0d6eafda99ecf58__9418]
[  192.551425] irq event stamp: 6995349
[  192.551689] hardirqs last  enabled at (6995349): [<ffffffff81895ac2>] sysret_check+0x26/0x10d
[  192.551956] hardirqs last disabled at (6995348): [<ffffffff81895aae>] sysret_check+0x12/0x10d
[  192.552210] softirqs last  enabled at (6994898): [<ffffffff810bac14>] __do_softirq+0x1a4/0x470
[  192.552461] softirqs last disabled at (6994893): [<ffffffff8189923c>] call_softirq+0x1c/0x30
[  192.552715] CPU: 5 PID: 6923 Comm: cc1 Kdump: loaded Tainted: G           OEL ------------   3.10.0-1127.19.1.el7.x86_64.debug #1
[  192.553212] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20180531_142017-buildhw-08.phx2.fedoraproject.org-1.fc28 04/01/2014
[  192.553734] task: ffff8801721ac000 ti: ffff88017239c000 task.ti: ffff88017239c000
[  192.554009] RIP: 0010:[<ffffffff8114e322>]  [<ffffffff8114e322>] generic_exec_single+0x102/0x200
[  192.554278] RSP: 0018:ffff88017239fc00  EFLAGS: 00000202
[  192.554547] RAX: 0000000000000010 RBX: ffffffff8188b543 RCX: 0000000000000030
[  192.554816] RDX: 0000000000000010 RSI: 0000000000000010 RDI: 0000000000000286
[  192.555078] RBP: ffff88017239fc60 R08: ffffffff818b3ec0 R09: 0000000000000000
[  192.555340] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff8119a597
[  192.555612] R13: ffff88017239fb78 R14: ffff8801721ac000 R15: ffff88017239c000
[  192.555880] FS:  00007f0c3fa0a840(0000) GS:ffff880179000000(0000) knlGS:0000000000000000
[  192.556148] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  192.556419] CR2: 00007f0c3f9e9000 CR3: 000000017086e000 CR4: 0000000000360fe0
[  192.556704] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  192.556988] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  192.557261] Call Trace:
[  192.557537]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  192.557821]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  192.558092]  [<ffffffff8114e4e0>] smp_call_function_single+0x80/0xe0
[  192.558365]  [<ffffffff81413e3d>] ? cpumask_next_and+0x4d/0xb0
[  192.558643]  [<ffffffff8108d1e0>] ? leave_mm+0x1d0/0x1d0
[  192.558919]  [<ffffffff8114eb41>] smp_call_function_many+0x2c1/0x320
[  192.559192]  [<ffffffff8108d3a8>] native_flush_tlb_others+0xb8/0xc0
[  192.559467]  [<ffffffff8108d42b>] flush_tlb_mm_range+0x7b/0x160
[  192.559748]  [<ffffffff812414b6>] tlb_flush_mmu_tlbonly+0xa6/0xc0
[  192.560028]  [<ffffffff8124337f>] arch_tlb_finish_mmu+0x3f/0x80
[  192.560304]  [<ffffffff812434a3>] tlb_finish_mmu+0x23/0x30
[  192.560585]  [<ffffffff8124d1c4>] unmap_region+0xf4/0x140
[  192.560859]  [<ffffffff8124d7d1>] ? __vma_rb_erase+0x121/0x220
[  192.561122]  [<ffffffff8124fa05>] do_munmap+0x2a5/0x480
[  192.561381]  [<ffffffff8124fc48>] vm_munmap+0x68/0xb0
[  192.561639]  [<ffffffff81250f42>] SyS_munmap+0x22/0x30
[  192.561896]  [<ffffffff81895a92>] system_call_fastpath+0x25/0x2a

1-stap_79e089a8f5becc466d80561a9e95aaf3_1884.c

#define STAP_MSG_RUNTIME_H_01 "myproc-unprivileged tapset function called without is_myproc checking for pid %d (euid %d)"
#define STAP_MSG_LOC2C_01 "read fault [man error::fault] at 0x%lx"
#define STAP_MSG_LOC2C_02 "write fault [man error::fault] at 0x%lx"
#define STAP_MSG_LOC2C_03 "divide by zero in DWARF operand (%s)"
#define STAP_MSG_LOC2C_04 "register access fault [man error::fault]"
#define STAP_VERSION(a, b) ( ((a) << 8) + (b) )
#ifndef STAP_COMPAT_VERSION
#define STAP_COMPAT_VERSION STAP_VERSION(4, 4)
#endif
#pragma GCC diagnostic ignored "-Wtautological-compare"
#include "runtime_defines.h"
#include "linux/perf_read.h"
#define STP_PR_STAPUSR 0x2
#define STP_PR_STAPSYS 0x4
#define STP_PR_STAPDEV 0x8
#define STP_PRIVILEGE 0x8
int stp_required_privilege __attribute__ ((section (".stap_privilege"))) = STP_PRIVILEGE;
#include "stap_common.h"
static void systemtap_module_refresh (const char* modname);
#include "runtime.h"
#include <linux/mutex.h>
static DEFINE_MUTEX(module_refresh_mutex);
#include <linux/version.h>
#if LINUX_VERSION_CODE >= KERNEL_VERSION(2,6,17)
#define STP_ON_THE_FLY_TIMER_ENABLE
#endif

struct context {
  #include "common_probe_context.h"
  union {
    struct probe_6333_locals {
      union { /* block_statement: /home/sultan/systemtap/testsuite/systemtap.base/tracepoints2.stp:1 */
        struct { /* source: /home/sultan/systemtap/testsuite/systemtap.base/tracepoints2.stp:2 */
          string_t __tmp0;
          string_t __tmp1;
        };
      };
    } probe_6333;
    struct probe_6334_locals {
    } probe_6334;
  } probe_locals;
  union {
    struct function___global_error__overload_0_locals {
      const char * l_msg;
      /* no return value */
    } function___global_error__overload_0;
    struct function___global_exit__overload_0_locals {
      /* no return value */
    } function___global_exit__overload_0;
  } locals [MAXNESTING+1];
  #if MAXNESTING < 0
  #error "MAXNESTING must be positive"
  #endif
  #ifndef STP_LEGACY_PRINT
  union {
    struct stp_printf_1_locals {
      const char* arg0;
      const char* arg1;
    } stp_printf_1;
  } printf_locals;
  #endif // STP_LEGACY_PRINT
};

#include "runtime_context.h"
#ifndef STP_LEGACY_PRINT

static void stp_printf_1 (struct context* __restrict__ c) {
  struct stp_printf_1_locals * __restrict__ l = & c->printf_locals.stp_printf_1;
  char *str = NULL, *end = NULL;
  const char *src;
  int width;
  int precision;
  unsigned long ptr_value;
  int num_bytes;
  unsigned long irqflags;
  (void) width;
  (void) precision;
  (void) ptr_value;
  (void) num_bytes;
  num_bytes = 0;
  width = -1;
  precision = -1;
  num_bytes += _stp_vsprint_memory_size(l->arg0, width, precision, 's', 0);
  num_bytes += sizeof(":") - 1;
  width = -1;
  precision = -1;
  num_bytes += _stp_vsprint_memory_size(l->arg1, width, precision, 's', 0);
  num_bytes += sizeof("\n") - 1;
  num_bytes = clamp(num_bytes, 0, STP_BUFFER_SIZE);
  local_irq_save(irqflags);
  str = (char*)_stp_reserve_bytes(num_bytes);
  end = str ? str + num_bytes - 1 : 0;
  if (str && str <= end) {
    width = -1;
    precision = -1;
    str = _stp_vsprint_memory(str, end, l->arg0, width, precision, 's', 0);
    src = ":";
    while (*src && str <= end)
      *str++ = *src++;
    width = -1;
    precision = -1;
    str = _stp_vsprint_memory(str, end, l->arg1, width, precision, 's', 0);
    src = "\n";
    while (*src && str <= end)
      *str++ = *src++;
  }
exit:
local_irq_restore(irqflags);
}
#endif // STP_LEGACY_PRINT
static atomic_t need_module_refresh = ATOMIC_INIT(0);
#include <linux/workqueue.h>
static struct work_struct module_refresher_work;
#if LINUX_VERSION_CODE < KERNEL_VERSION(2,6,20)
static void module_refresher(void *data) {
#else
static void module_refresher(struct work_struct *work) {
#endif
  systemtap_module_refresh(NULL);
}
#ifdef STP_ON_THE_FLY_TIMER_ENABLE
#include "timer.h"
static struct hrtimer module_refresh_timer;
#ifndef STP_ON_THE_FLY_INTERVAL
#define STP_ON_THE_FLY_INTERVAL (100*1000*1000)
#endif
hrtimer_return_t module_refresh_timer_cb(struct hrtimer *timer) {
  if (atomic_cmpxchg(&need_module_refresh, 1, 0) == 1)
    schedule_work(&module_refresher_work);
  hrtimer_set_expires(timer,
    ktime_add(hrtimer_get_expires(timer),
              ktime_set(0, STP_ON_THE_FLY_INTERVAL))); 
  return HRTIMER_RESTART;
}
#endif /* STP_ON_THE_FLY_TIMER_ENABLE */
#include "namespaces.h"

struct stp_globals {};

#include "common_session_state.h"
#include "probe_lock.h" 
#ifdef STAP_NEED_GETTIMEOFDAY
#include "time.c"
#endif

static void function___global_error__overload_0 (struct context * __restrict__ c);

static void function___global_exit__overload_0 (struct context * __restrict__ c);

struct stap_probe {
  const size_t index;
  void (* const ph) (struct context*);
  unsigned cond_enabled:1;
  #if defined(STP_TIMING) || defined(STP_ALIBI)
  const char * const location;
  const char derivation[33];
  #define STAP_PROBE_INIT_TIMING(L, D) .location=(L), .derivation=(D),
  #else
  #define STAP_PROBE_INIT_TIMING(L, D)
  #endif
  const char pp[39];
  #ifdef STP_NEED_PROBE_NAME
  const char pn[15];
  #define STAP_PROBE_INIT_NAME(PN) .pn=(PN),
  #else
  #define STAP_PROBE_INIT_NAME(PN)
  #endif
  #define STAP_PROBE_INIT(I, PH, PP, PN, L, D) { .index=(I), .ph=(PH), .cond_enabled=1, .pp=(PP), STAP_PROBE_INIT_NAME(PN) STAP_PROBE_INIT_TIMING(L, D) }
} static stap_probes[];

static void probe_6333 (struct context * __restrict__ c) {
  __label__ deref_fault;
  __label__ out;
  static const struct stp_probe_lock locks[] = {
  };
  struct probe_6333_locals * __restrict__ l = & c->probe_locals.probe_6333;
  (void) l;
  #if ! STP_PRIVILEGE_CONTAINS (STP_PRIVILEGE, STP_PR_STAPDEV) && \
      ! STP_PRIVILEGE_CONTAINS (STP_PRIVILEGE, STP_PR_STAPSYS)
  #error Internal Error: Probe kernel.trace("sched:sched_switch") generated in --unprivileged mode
  #endif
  if (c->actionremaining < 2) { c->last_error = "MAXACTION exceeded"; goto out; }
  {
    if (c->locked == 0) {
      if (!stp_lock_probe(locks, ARRAY_SIZE(locks)))
        goto out;
      else
        c->locked = 1;
    } else if (unlikely(c->locked == 2)) {
      _stp_error("invalid lock state");
    }
    if (c->locked == 1) {
      stp_unlock_probe(locks, ARRAY_SIZE(locks));
      c->locked = 2;
    }
    (void) 
    ({
      strlcpy (l->__tmp0, (((const char *) (/* string */ /* pure */ c->ips.tp.tracepoint_system ? c->ips.tp.tracepoint_system : ""))), MAXSTRINGLEN);
      strlcpy (l->__tmp1, (((const char *) (/* string */ /* pure */ c->ips.tp.tracepoint_name ? c->ips.tp.tracepoint_name : ""))), MAXSTRINGLEN);
      #ifndef STP_LEGACY_PRINT
        c->printf_locals.stp_printf_1.arg0 = l->__tmp0;
        c->printf_locals.stp_printf_1.arg1 = l->__tmp1;
        stp_printf_1 (c);
      #else // STP_LEGACY_PRINT
        _stp_printf ("%s:%s\n", l->__tmp0, l->__tmp1);
      #endif // STP_LEGACY_PRINT
      if (unlikely(c->last_error || c->aborted)) goto out;
      ((int64_t)0LL);
    });
    
    (void) 
    ({
      c->last_stmt = "identifier 'exit' at /home/sultan/systemtap/testsuite/systemtap.base/tracepoints2.stp:10:4";
      function___global_exit__overload_0 (c);
      if (unlikely(c->last_error || c->aborted)) goto out;
      (void) 0;
    });
    
  }
deref_fault: __attribute__((unused));
out:
  if (c->locked == 1) {
    stp_unlock_probe(locks, ARRAY_SIZE(locks));
    c->locked = 2;
  }
  _stp_print_flush();
}


static void probe_6334 (struct context * __restrict__ c) {
  __label__ deref_fault;
  __label__ out;
  static const struct stp_probe_lock locks[] = {
  };
  struct probe_6334_locals * __restrict__ l = & c->probe_locals.probe_6334;
  (void) l;
  if (c->actionremaining < 1) { c->last_error = "MAXACTION exceeded"; goto out; }
  if (c->locked == 0) {
    if (!stp_lock_probe(locks, ARRAY_SIZE(locks)))
      goto out;
    else
      c->locked = 1;
  } else if (unlikely(c->locked == 2)) {
    _stp_error("invalid lock state");
  }
  if (c->locked == 1) {
    stp_unlock_probe(locks, ARRAY_SIZE(locks));
    c->locked = 2;
  }
  (void) 
  ({
    c->locals[c->nesting+1].function___global_error__overload_0.l_msg = "probe timeout after 15 minutes";
    c->last_stmt = "identifier 'error' at <input1>:1:20";
    function___global_error__overload_0 (c);
    if (unlikely(c->last_error || c->aborted)) goto out;
    (void) 0;
  });
deref_fault: __attribute__((unused));
out:
  if (c->locked == 1) {
    stp_unlock_probe(locks, ARRAY_SIZE(locks));
    c->locked = 2;
  }
  _stp_print_flush();
}

static struct stap_probe stap_probes[] = {
  STAP_PROBE_INIT(0, &probe_6333, "kernel.trace(\"sched:sched_switch\")", "my_probe", "/home/sultan/systemtap/testsuite/systemtap.base/tracepoints2.stp:9:7", " from: my_probe from: my_probe"),
  STAP_PROBE_INIT(1, &probe_6334, "timer.s(900)", "timer.s(900)", "<input1>:1:1", " from: timer.s(900)"),
};

static void function___global_error__overload_0 (struct context* __restrict__ c) {
  __label__ deref_fault;
  __label__ out;
  struct function___global_error__overload_0_locals *  __restrict__ l = & c->locals[c->nesting+1].function___global_error__overload_0;
  (void) l;
  #define CONTEXT c
  #define THIS l
  #define STAP_ARG_msg THIS->l_msg
  c->last_stmt = "identifier 'error' at /home/sultan/stap-vanilla/share/systemtap/tapset/logging.stp:115:10";
  if (unlikely (c->nesting+1 >= MAXNESTING)) {
    c->last_error = "MAXNESTING exceeded";
    return;
  } else {
    c->nesting ++;
  }
  c->next = 0;
  #define STAP_NEXT do { c->next = 1; goto out; } while(0)
  #define STAP_RETURN() do { goto out; } while(0)
  #define STAP_PRINTF(fmt, ...) do { _stp_printf(fmt, ##__VA_ARGS__); } while (0)
  #define STAP_ERROR(...) do { snprintf(CONTEXT->error_buffer, MAXSTRINGLEN, __VA_ARGS__); CONTEXT->last_error = CONTEXT->error_buffer; goto out; } while (0)
  #define return goto out
  if (c->actionremaining < 0) { c->last_error = "MAXACTION exceeded";goto out; }
  {
     /* unprivileged */ /* unmodified-fnargs */
     /* NB: we used to reuse msg[] for an assignment to last_error; this
      is clearer & safer. */
     strlcpy (CONTEXT->error_buffer, STAP_ARG_msg, MAXSTRINGLEN);
     CONTEXT->last_error = CONTEXT->error_buffer;
     CONTEXT->last_stmt = NULL;
  
  }
  #undef return
  #undef STAP_PRINTF
  #undef STAP_ERROR
  #undef STAP_RETURN
deref_fault: __attribute__((unused));
out: __attribute__((unused));
  c->nesting --;
  #undef CONTEXT
  #undef THIS
  #undef STAP_NEXT
  #undef STAP_ARG_msg
  #undef STAP_RETVALUE
}


static void function___global_exit__overload_0 (struct context* __restrict__ c) {
  __label__ deref_fault;
  __label__ out;
  struct function___global_exit__overload_0_locals *  __restrict__ l = & c->locals[c->nesting+1].function___global_exit__overload_0;
  (void) l;
  #define CONTEXT c
  #define THIS l
  c->last_stmt = "identifier 'exit' at /home/sultan/stap-vanilla/share/systemtap/tapset/logging.stp:63:10";
  if (unlikely (c->nesting+1 >= MAXNESTING)) {
    c->last_error = "MAXNESTING exceeded";
    return;
  } else {
    c->nesting ++;
  }
  c->next = 0;
  #define STAP_NEXT do { c->next = 1; goto out; } while(0)
  #define STAP_RETURN() do { goto out; } while(0)
  #define STAP_PRINTF(fmt, ...) do { _stp_printf(fmt, ##__VA_ARGS__); } while (0)
  #define STAP_ERROR(...) do { snprintf(CONTEXT->error_buffer, MAXSTRINGLEN, __VA_ARGS__); CONTEXT->last_error = CONTEXT->error_buffer; goto out; } while (0)
  #define return goto out
  if (c->actionremaining < 0) { c->last_error = "MAXACTION exceeded";goto out; }
  {
     /* unprivileged */
     atomic_set (session_state(), STAP_SESSION_STOPPING);
     _stp_exit ();
  
  }
  #undef return
  #undef STAP_PRINTF
  #undef STAP_ERROR
  #undef STAP_RETURN
deref_fault: __attribute__((unused));
out: __attribute__((unused));
  c->nesting --;
  #undef CONTEXT
  #undef THIS
  #undef STAP_NEXT
  #undef STAP_RETVALUE
}


/* ---- tracepoint probes ---- */
#include <linux/stp_tracepoint.h>


STP_TRACE_ENTER_REAL_NOARGS(enter_real_tracepoint_probe_0)
{
  const struct stap_probe * const probe = (&stap_probes[0]);
  #ifdef STP_ALIBI
  atomic_inc(probe_alibi(probe->index));
  #else
  struct context* __restrict__ c = NULL;
  #if !INTERRUPTIBLE
  unsigned long flags;
  #endif
  #ifdef STP_TIMING
  Stat stat = probe_timing(probe->index);
  #endif
  #if defined(STP_TIMING) || defined(STP_OVERLOAD)
  cycles_t cycles_atstart = get_cycles ();
  #endif
  #if !INTERRUPTIBLE
  local_irq_save (flags);
  #endif
  if (unlikely ((((unsigned long) (& c)) & (THREAD_SIZE-1))
    < (MINSTACKSPACE + sizeof (struct thread_info)))) {
    atomic_inc (skipped_count());
    #ifdef STP_TIMING
    atomic_inc (skipped_count_lowstack());
    #endif
    goto probe_epilogue;
  }
  {
    unsigned sess_state = atomic_read (session_state());
    #ifdef DEBUG_PROBES
    _stp_dbug(__FUNCTION__, __LINE__, "session state: %d, expecting STAP_SESSION_RUNNING (%d)", sess_state, STAP_SESSION_RUNNING);
    #endif
    if (sess_state != STAP_SESSION_RUNNING)
    goto probe_epilogue;
  }
  c = _stp_runtime_entryfn_get_context();
  if (!c) {
    #if !INTERRUPTIBLE
    atomic_inc (skipped_count());
    #endif
    #ifdef STP_TIMING
    atomic_inc (skipped_count_reentrant());
    #endif
    goto probe_epilogue;
  }
  
  c->aborted = 0;
  c->locked = 0;
  c->last_stmt = 0;
  c->last_error = 0;
  c->nesting = -1;
  c->uregs = 0;
  c->kregs = 0;
  c->sregs = 0;
  #if defined __ia64__
  c->unwaddr = 0;
  #endif
  c->probe_point = probe->pp;
  #ifdef STP_NEED_PROBE_NAME
  c->probe_name = probe->pn;
  #endif
  c->probe_type = stp_probe_type_tracepoint;
  memset(&c->ips, 0, sizeof(c->ips));
  c->user_mode_p = 0; c->full_uregs_p = 0; 
  #ifdef STAP_NEED_REGPARM
  c->regparm = 0;
  #endif
  #if INTERRUPTIBLE
  c->actionremaining = MAXACTION_INTERRUPTIBLE;
  #else
  c->actionremaining = MAXACTION;
  #endif
  #if defined(STP_NEED_UNWIND_DATA)
  c->uwcache_user.state = uwcache_uninitialized;
  c->uwcache_kernel.state = uwcache_uninitialized;
  #endif
  #if defined(STAP_NEED_CONTEXT_RETURNVAL)
  c->returnval_override_p = 0;
  c->returnval_override = 0;
  #endif
  c->ips.tp.tracepoint_system = "sched";
  c->ips.tp.tracepoint_name = "sched_switch";
  (*probe->ph) (c);
  #if defined(STP_TIMING) || defined(STP_OVERLOAD)
  {
    cycles_t cycles_atend = get_cycles ();
    int32_t cycles_elapsed = ((int32_t)cycles_atend > (int32_t)cycles_atstart)
      ? ((int32_t)cycles_atend - (int32_t)cycles_atstart)
      : (~(int32_t)0) - (int32_t)cycles_atstart + (int32_t)cycles_atend + 1;
    #ifdef STP_TIMING
    if (likely (stat)) _stp_stat_add(stat, cycles_elapsed, 1, 1, 1, 1, 0);
    #endif
    #ifdef STP_OVERLOAD
    {
      cycles_t interval = (cycles_atend > c->cycles_base)
        ? (cycles_atend - c->cycles_base)
        : (STP_OVERLOAD_INTERVAL + 1);
      c->cycles_sum += cycles_elapsed;
      if (interval > STP_OVERLOAD_INTERVAL) {
        if (c->cycles_sum > STP_OVERLOAD_THRESHOLD) {
          _stp_error ("probe overhead (%lld cycles) exceeded threshold (%lld cycles) in last %lld cycles", (long long) c->cycles_sum, STP_OVERLOAD_THRESHOLD, STP_OVERLOAD_INTERVAL);
          atomic_set (session_state(), STAP_SESSION_ERROR);
          atomic_inc (error_count());
        }
        c->cycles_base = cycles_atend;
        c->cycles_sum = 0;
      }
    }
    #endif
  }
  #endif
  c->probe_point = 0;
  #ifdef STP_NEED_PROBE_NAME
  c->probe_name = 0;
  #endif
  c->probe_type = 0;
  if (unlikely (c->last_error)) {
    if (c->last_stmt != NULL)
      _stp_softerror ("%s near %s", c->last_error, c->last_stmt);
    else
      _stp_softerror ("%s", c->last_error);
    atomic_inc (error_count());
    if (atomic_read (error_count()) > MAXERRORS) {
      atomic_set (session_state(), STAP_SESSION_ERROR);
      _stp_exit ();
    }
  }
probe_epilogue:
  if (unlikely (atomic_read (skipped_count()) > MAXSKIPPED)) {
    if (unlikely (pseudo_atomic_cmpxchg(session_state(), STAP_SESSION_RUNNING, STAP_SESSION_ERROR) == STAP_SESSION_RUNNING))
    _stp_error ("Skipped too many probes, check MAXSKIPPED or try again with stap -t for more details.");
  }
  _stp_runtime_entryfn_put_context(c);
  #if !INTERRUPTIBLE
  local_irq_restore (flags);
  #endif
  #endif // STP_ALIBI
}
int register_tracepoint_probe_0(void);
void unregister_tracepoint_probe_0(void);
static struct stap_tracepoint_probe {
  int (*reg)(void);
  void (*unreg)(void);
} stap_tracepoint_probes[] = {
  { .reg=&register_tracepoint_probe_0, .unreg=&unregister_tracepoint_probe_0 },
};

/* ---- hrtimer probes ---- */
#include "timer.c"
static struct stap_hrtimer_probe stap_hrtimer_probes [1] = {
  { .probe=(&stap_probes[1]), .intrv=900000000000LL, .rnd=0LL },
};

static hrtimer_return_t _stp_hrtimer_notify_function (struct hrtimer *timer) {
  int rc = HRTIMER_NORESTART;
  struct stap_hrtimer_probe *stp = container_of(timer, struct stap_hrtimer_probe, hrtimer);
  if ((atomic_read (session_state()) == STAP_SESSION_STARTING) ||
      (atomic_read (session_state()) == STAP_SESSION_RUNNING)) {
    _stp_hrtimer_update(stp);
    rc = HRTIMER_RESTART;
  }
  {
    #ifdef STP_ALIBI
    atomic_inc(probe_alibi(stp->probe->index));
    #else
    struct context* __restrict__ c = NULL;
    #if !INTERRUPTIBLE
    unsigned long flags;
    #endif
    #ifdef STP_TIMING
    Stat stat = probe_timing(stp->probe->index);
    #endif
    #if defined(STP_TIMING) || defined(STP_OVERLOAD)
    cycles_t cycles_atstart = get_cycles ();
    #endif
    #if !INTERRUPTIBLE
    local_irq_save (flags);
    #endif
    if (unlikely ((((unsigned long) (& c)) & (THREAD_SIZE-1))
      < (MINSTACKSPACE + sizeof (struct thread_info)))) {
      atomic_inc (skipped_count());
      #ifdef STP_TIMING
      atomic_inc (skipped_count_lowstack());
      #endif
      goto probe_epilogue;
    }
    {
      unsigned sess_state = atomic_read (session_state());
      #ifdef DEBUG_PROBES
      _stp_dbug(__FUNCTION__, __LINE__, "session state: %d, expecting STAP_SESSION_RUNNING (%d)", sess_state, STAP_SESSION_RUNNING);
      #endif
      if (sess_state != STAP_SESSION_RUNNING)
      goto probe_epilogue;
    }
    c = _stp_runtime_entryfn_get_context();
    if (!c) {
      #if !INTERRUPTIBLE
      atomic_inc (skipped_count());
      #endif
      #ifdef STP_TIMING
      atomic_inc (skipped_count_reentrant());
      #endif
      goto probe_epilogue;
    }
    
    c->aborted = 0;
    c->locked = 0;
    c->last_stmt = 0;
    c->last_error = 0;
    c->nesting = -1;
    c->uregs = 0;
    c->kregs = 0;
    c->sregs = 0;
    #if defined __ia64__
    c->unwaddr = 0;
    #endif
    c->probe_point = stp->probe->pp;
    #ifdef STP_NEED_PROBE_NAME
    c->probe_name = stp->probe->pn;
    #endif
    c->probe_type = stp_probe_type_hrtimer;
    memset(&c->ips, 0, sizeof(c->ips));
    c->user_mode_p = 0; c->full_uregs_p = 0; 
    #ifdef STAP_NEED_REGPARM
    c->regparm = 0;
    #endif
    #if INTERRUPTIBLE
    c->actionremaining = MAXACTION_INTERRUPTIBLE;
    #else
    c->actionremaining = MAXACTION;
    #endif
    #if defined(STP_NEED_UNWIND_DATA)
    c->uwcache_user.state = uwcache_uninitialized;
    c->uwcache_kernel.state = uwcache_uninitialized;
    #endif
    #if defined(STAP_NEED_CONTEXT_RETURNVAL)
    c->returnval_override_p = 0;
    c->returnval_override = 0;
    #endif
    (*stp->probe->ph) (c);
    if (atomic_cmpxchg(&need_module_refresh, 1, 0) == 1)
      schedule_work(&module_refresher_work);
    #if defined(STP_TIMING) || defined(STP_OVERLOAD)
    {
      cycles_t cycles_atend = get_cycles ();
      int32_t cycles_elapsed = ((int32_t)cycles_atend > (int32_t)cycles_atstart)
        ? ((int32_t)cycles_atend - (int32_t)cycles_atstart)
        : (~(int32_t)0) - (int32_t)cycles_atstart + (int32_t)cycles_atend + 1;
      #ifdef STP_TIMING
      if (likely (stat)) _stp_stat_add(stat, cycles_elapsed, 1, 1, 1, 1, 0);
      #endif
      #ifdef STP_OVERLOAD
      {
        cycles_t interval = (cycles_atend > c->cycles_base)
          ? (cycles_atend - c->cycles_base)
          : (STP_OVERLOAD_INTERVAL + 1);
        c->cycles_sum += cycles_elapsed;
        if (interval > STP_OVERLOAD_INTERVAL) {
          if (c->cycles_sum > STP_OVERLOAD_THRESHOLD) {
            _stp_error ("probe overhead (%lld cycles) exceeded threshold (%lld cycles) in last %lld cycles", (long long) c->cycles_sum, STP_OVERLOAD_THRESHOLD, STP_OVERLOAD_INTERVAL);
            atomic_set (session_state(), STAP_SESSION_ERROR);
            atomic_inc (error_count());
          }
          c->cycles_base = cycles_atend;
          c->cycles_sum = 0;
        }
      }
      #endif
    }
    #endif
    c->probe_point = 0;
    #ifdef STP_NEED_PROBE_NAME
    c->probe_name = 0;
    #endif
    c->probe_type = 0;
    if (unlikely (c->last_error)) {
      if (c->last_stmt != NULL)
        _stp_softerror ("%s near %s", c->last_error, c->last_stmt);
      else
        _stp_softerror ("%s", c->last_error);
      atomic_inc (error_count());
      if (atomic_read (error_count()) > MAXERRORS) {
        atomic_set (session_state(), STAP_SESSION_ERROR);
        _stp_exit ();
      }
    }
  probe_epilogue:
    if (unlikely (atomic_read (skipped_count()) > MAXSKIPPED)) {
      if (unlikely (pseudo_atomic_cmpxchg(session_state(), STAP_SESSION_RUNNING, STAP_SESSION_ERROR) == STAP_SESSION_RUNNING))
      _stp_error ("Skipped too many probes, check MAXSKIPPED or try again with stap -t for more details.");
    }
    _stp_runtime_entryfn_put_context(c);
    #if !INTERRUPTIBLE
    local_irq_restore (flags);
    #endif
    #endif // STP_ALIBI
  }
  return rc;
}
#ifdef STAP_NEED_TRACEPOINTS
#include "linux/stp_tracepoint.c"
#endif

static int systemtap_module_init (void) {
  int rc = 0;
  int cpu;
  int i=0, j=0;
  const char *probe_point = "";
  might_sleep();
  rc = _stp_handle_kallsyms_lookups();
  if (rc) goto out;
  {
  #ifndef STP_NO_VERREL_CHECK
    const char* release = UTS_RELEASE;
    #ifdef STAPCONF_GENERATED_COMPILE
    const char* version = UTS_VERSION;
    #endif
    #ifdef STP_FULL_VERREL_CHECK
    if (strcmp (release, "3.10.0-1127.19.1.el7.x86_64.debug")) {
      _stp_error ("module release mismatch (%s vs %s)", release, "3.10.0-1127.19.1.el7.x86_64.debug");
      rc = -EINVAL;
    }
    #endif
    #ifdef STAPCONF_GENERATED_COMPILE
    if (strcmp (utsname()->version, version)) {
      _stp_error ("module version mismatch (%s vs %s), release %s", version, utsname()->version, release);
      rc = -EINVAL;
    }
    #endif
    #endif
    if (_stp_module_check()) rc = -EINVAL;
    if (_stp_privilege_credentials == 0) {
      if (STP_PRIVILEGE_CONTAINS(STP_PRIVILEGE, STP_PR_STAPDEV) ||
          STP_PRIVILEGE_CONTAINS(STP_PRIVILEGE, STP_PR_STAPUSR)) {
        _stp_privilege_credentials = STP_PRIVILEGE;
        #ifdef DEBUG_PRIVILEGE
          _dbug("User's privilege credentials default to %s\n",
                privilege_to_text(_stp_privilege_credentials));
        #endif
      }
      else {
        _stp_error ("Unable to verify that you have the required privilege credentials to run this module (%s required). You must use staprun version 1.7 or higher.",
                    privilege_to_text(STP_PRIVILEGE));
        rc = -EINVAL;
      }
    }
    else {
      #ifdef DEBUG_PRIVILEGE
        _dbug("User's privilege credentials provided as %s\n",
              privilege_to_text(_stp_privilege_credentials));
      #endif
      if (! STP_PRIVILEGE_CONTAINS(_stp_privilege_credentials, STP_PRIVILEGE)) {
        _stp_error ("Your privilege credentials (%s) are insufficient to run this module (%s required).",
                    privilege_to_text(_stp_privilege_credentials), privilege_to_text(STP_PRIVILEGE));
        rc = -EINVAL;
      }
    }
  }
  if (rc) goto out;
  rc = stp_session_init();
  if (rc) {
    _stp_error ("couldn't initialize the main session (rc %d)", rc);
    goto out;
  }
  if (atomic_cmpxchg(session_state(), STAP_SESSION_UNINITIALIZED, STAP_SESSION_STARTING) != STAP_SESSION_UNINITIALIZED) {
    _stp_error ("session has already been initialized");
    return -EALREADY;
  }
  #ifdef STAP_NEED_GETTIMEOFDAY
  rc = _stp_init_time();
  if (rc) {
    _stp_error ("couldn't initialize gettimeofday");
    goto out;
  }
  #endif
  #ifdef STAP_NEED_TRACEPOINTS
  rc = stp_tracepoint_init();
  if (rc) {
    _stp_error ("couldn't initialize tracepoints");
    goto out;
  }
  #endif
  #ifdef STP_NEED_UNWIND_DATA
  rc = _stp_init_stack();
  if (rc) {
    _stp_error ("couldn't initialize stack support");
    goto out;
  }
  #endif
  (void) probe_point;
  (void) i;
  (void) j;
  rc = _stp_runtime_contexts_alloc();
  if (rc != 0)
    goto out;
  _stp_print_kernel_info("tracepoints2.stp", "4.4/0.177", (num_online_cpus() * sizeof(struct context)), 2);
  #if LINUX_VERSION_CODE < KERNEL_VERSION(2,6,20)
  INIT_WORK(&module_refresher_work, module_refresher, NULL);
  #else
  INIT_WORK(&module_refresher_work, module_refresher);
  #endif
  /* init tracepoint probes */
  for (i=0; i<1; i++) {
    rc = stap_tracepoint_probes[i].reg();
    if (rc) {
      for (j=i-1; j>=0; j--)
        stap_tracepoint_probes[j].unreg();
      break;
    }
  }
  if (rc) {
    if (probe_point)
      _stp_error ("probe %s registration error (rc %d)", probe_point, rc);
    atomic_set (session_state(), STAP_SESSION_ERROR);
    goto out;
  }
  _stp_hrtimer_init();
  for (i=0; i<1; i++) {
    struct stap_hrtimer_probe* stp = & stap_hrtimer_probes [i];
    probe_point = stp->probe->pp;
    rc = _stp_hrtimer_create(stp, _stp_hrtimer_notify_function);
    if (rc) {
      for (j=i-1; j>=0; j--) {
        _stp_hrtimer_cancel(& stap_hrtimer_probes[j]);
        stap_hrtimer_probes[j].enabled = 0;
      }
      break;
    }
    if (!stp->probe->cond_enabled) {
      dbug_otf("not starting (hrtimer) pidx %zu\n",
      stp->probe->index);
      continue;
    }
    rc = _stp_hrtimer_start(stp);
    if (rc) {
      for (j=i-1; j>=0; j--) {
        _stp_hrtimer_cancel(& stap_hrtimer_probes[j]);
        stap_hrtimer_probes[j].enabled = 0;
      }
      break;
    }
    stp->enabled = 1;
  }
  if (rc) {
    if (probe_point)
      _stp_error ("probe %s registration error (rc %d)", probe_point, rc);
    atomic_set (session_state(), STAP_SESSION_ERROR);
    /* deregister tracepoint probes */
    for (i=0; i<1; i++)
      stap_tracepoint_probes[i].unreg();
    goto out;
  }
  atomic_cmpxchg(session_state(), STAP_SESSION_STARTING, STAP_SESSION_RUNNING);
  #ifdef STP_ON_THE_FLY_TIMER_ENABLE
  hrtimer_init(&module_refresh_timer, CLOCK_MONOTONIC,
               HRTIMER_MODE_REL);
  module_refresh_timer.function = &module_refresh_timer_cb;
  #endif /* STP_ON_THE_FLY_TIMER_ENABLE */
  return 0;
deref_fault: __attribute__((unused));
out:
  atomic_set (session_state(), STAP_SESSION_STOPPED);
  stp_synchronize_sched();
  #ifdef STAP_NEED_TRACEPOINTS
   stp_tracepoint_exit();
  #endif
  #ifdef STAP_NEED_GETTIMEOFDAY
   _stp_kill_time();
  #endif
  _stp_runtime_contexts_free();
  return rc;
}


static void systemtap_module_refresh (const char *modname) {
  int state;
  int i=0, j=0;
  #if defined(STP_TIMING)
  cycles_t cycles_atstart = get_cycles();
  #endif
  mutex_lock(&module_refresh_mutex);
  state = atomic_read (session_state());
  if (state != STAP_SESSION_RUNNING && state != STAP_SESSION_STARTING) {
    
    mutex_unlock(&module_refresh_mutex);
    return;
  }
  (void) i;
  (void) j;
  for (i=0; i <1; i++) {
    struct stap_hrtimer_probe* stp = &stap_hrtimer_probes[i];
    if (!stp->enabled && stp->probe->cond_enabled) {
      dbug_otf("enabling (hrtimer) pidx %zu\n", stp->probe->index);
      _stp_hrtimer_start(stp);
    } else if (stp->enabled && !stp->probe->cond_enabled) {
      dbug_otf("disabling (hrtimer) pidx %zu\n", stp->probe->index);
      _stp_hrtimer_cancel(stp);
    }
    stp->enabled = stp->probe->cond_enabled;
  }
  #if defined(STP_TIMING)
  if (likely(g_refresh_timing)) {
    cycles_t cycles_atend = get_cycles ();
    int32_t cycles_elapsed = ((int32_t)cycles_atend > (int32_t)cycles_atstart)
      ? ((int32_t)cycles_atend - (int32_t)cycles_atstart)
      : (~(int32_t)0) - (int32_t)cycles_atstart + (int32_t)cycles_atend + 1;
    _stp_stat_add(g_refresh_timing, cycles_elapsed, 1, 1, 1, 1, 1);
  }
  #endif
  mutex_unlock(&module_refresh_mutex);
}


static void systemtap_module_exit (void) {
  int i=0, j=0;
  (void) i;
  (void) j;
  if (atomic_read (session_state()) == STAP_SESSION_STARTING)
    return;
  if (atomic_read (session_state()) == STAP_SESSION_RUNNING)
    atomic_set (session_state(), STAP_SESSION_STOPPING);
  #ifdef STP_ON_THE_FLY_TIMER_ENABLE
  hrtimer_cancel(&module_refresh_timer);
  #endif
  stp_synchronize_sched();
  mutex_lock(&module_refresh_mutex);
  for (i=0; i<1; i++)
    _stp_hrtimer_delete(& stap_hrtimer_probes[i]);
  /* deregister tracepoint probes */
  for (i=0; i<1; i++)
    stap_tracepoint_probes[i].unreg();
  mutex_unlock(&module_refresh_mutex);
  stp_synchronize_sched();
  _stp_runtime_context_wait();
  atomic_set (session_state(), STAP_SESSION_STOPPED);
  stp_synchronize_sched();
  _stp_runtime_contexts_free();
  #ifdef STAP_NEED_TRACEPOINTS
   stp_tracepoint_exit();
  #endif
  #ifdef STAP_NEED_GETTIMEOFDAY
   _stp_kill_time();
  #endif
  preempt_disable();
  #if defined(STP_TIMING) || defined(STP_ALIBI)
  _stp_printf("----- probe hit report: \n");
  for (i = 0; i < ARRAY_SIZE(stap_probes); ++i) {
    const struct stap_probe *const p = &stap_probes[i];
    #ifdef STP_ALIBI
    int alibi = atomic_read(probe_alibi(i));
    if (alibi)
      _stp_printf ("%s, (%s), hits: %d,%s, index: %d\n",
          p->pp, p->location, alibi, p->derivation, i);
    #endif
    #ifdef STP_TIMING
    if (likely (probe_timing(i))) {
      struct stat_data *stats = _stp_stat_get (probe_timing(i), 0);
      if (stats->count) {
        int64_t avg = _stp_div64 (NULL, stats->sum, stats->count);
        _stp_printf ("%s, (%s), hits: %lld, cycles: %lldmin/%lldavg/%lldmax, variance: %lld,%s, index: %d\n",
            p->pp, p->location, (long long) stats->count,
            (long long) stats->min, (long long) avg, (long long) stats->max,
            (long long) stats->variance, p->derivation, i);
      }
      _stp_stat_del (probe_timing(i));
    }
    #endif
  }
  #if defined(STP_TIMING)
  _stp_printf("----- refresh report:\n");
  if (likely (g_refresh_timing)) {
    struct stat_data *stats = _stp_stat_get (g_refresh_timing, 0);
    if (stats->count) {
      int64_t avg = _stp_div64 (NULL, stats->sum, stats->count);
      _stp_printf ("hits: %lld, cycles: %lldmin/%lldavg/%lldmax, variance: %lld\n",
          (long long) stats->count, (long long) stats->min, 
          (long long) avg, (long long) stats->max, (long long) stats->variance);
    }
    _stp_stat_del (g_refresh_timing);
  }
  #endif
  _stp_print_flush();
  #endif
  #ifdef STP_TIMING
  {
    int ctr;
  }
  _stp_print_flush();
  #endif
  if (atomic_read (skipped_count()) || atomic_read (error_count()) || atomic_read (skipped_count_reentrant())) {
    _stp_warn ("Number of errors: %d, skipped probes: %d\n", (int) atomic_read (error_count()), (int) atomic_read (skipped_count()));
    #ifdef STP_TIMING
    {
      int ctr;
      ctr = atomic_read (skipped_count_lowstack());
      if (ctr) _stp_warn ("Skipped due to low stack: %d\n", ctr);
      ctr = atomic_read (skipped_count_reentrant());
      if (ctr) _stp_warn ("Skipped due to reentrancy: %d\n", ctr);
      ctr = atomic_read (skipped_count_uprobe_reg());
      if (ctr) _stp_warn ("Skipped due to uprobe register failure: %d\n", ctr);
      ctr = atomic_read (skipped_count_uprobe_unreg());
      if (ctr) _stp_warn ("Skipped due to uprobe unregister failure: %d\n", ctr);
    }
    #endif
    _stp_print_flush();
  }
  preempt_enable_no_resched();
}


static int systemtap_kernel_module_init (void) {
  int rc = 0;
  int i=0, j=0;
  if (rc) {
    goto out;
  }
  if (rc) {
    goto out;
  }
out:
  return rc;
}


static void systemtap_kernel_module_exit (void) {
  int i=0, j=0;
}


MODULE_DESCRIPTION("systemtap-generated probe");
MODULE_LICENSE("GPL");

2-print-make-print-driver-safe-to-use-in-IRQ-context.patch

From 552f14aacae7aa81b4f28ec79ab428edd0513eb4 Mon Sep 17 00:00:00 2001
From: Sultan Alsawaf <sultan@openresty.com>
Date: Thu, 12 Nov 2020 16:02:29 -0800
Subject: [PATCH] print: make print driver safe to use in IRQ context

---
 runtime/linux/io.c            |  38 +++++---
 runtime/linux/print.c         | 175 ++++++++++++++++++++++------------
 runtime/print_flush.c         |  57 ++---------
 runtime/stack.c               |  22 +++--
 runtime/transport/transport.c |   8 +-
 runtime/vsprintf.c            |  12 ++-
 translate.cxx                 |  11 ++-
 7 files changed, 186 insertions(+), 137 deletions(-)

diff --git a/runtime/linux/io.c b/runtime/linux/io.c
index 74a032c52..be7100ff5 100644
--- a/runtime/linux/io.c
+++ b/runtime/linux/io.c
@@ -20,9 +20,6 @@
 
 #define WARN_STRING "WARNING: "
 #define ERR_STRING "ERROR: "
-#if (STP_LOG_BUF_LEN < 10) /* sizeof(WARN_STRING) */
-#error "STP_LOG_BUF_LEN is too short"
-#endif
 
 enum code { INFO=0, WARN, ERROR, DBUG };
 
@@ -31,25 +28,35 @@ static void _stp_vlog (enum code type, const char *func, int line, const char *f
 
 static void _stp_vlog (enum code type, const char *func, int line, const char *fmt, va_list args)
 {
+	struct _stp_log *log;
+	unsigned long flags;
+	size_t bytes_avail;
 	int num;
-	char *buf = per_cpu_ptr(Stp_lbuf, get_cpu());
+	char *buf;
 	int start = 0;
 
+	local_irq_save(flags);
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	bytes_avail = STP_BUFFER_SIZE - log->len;
+	if (unlikely(!bytes_avail))
+		goto restore_irqs;
+
+	buf = &log->buf[log->len];
 	if (type == DBUG) {
-		start = _stp_snprintf(buf, STP_LOG_BUF_LEN, "%s:%d: ", func, line);
+		start = _stp_snprintf(buf, bytes_avail, "%s:%d: ", func, line);
 	} else if (type == WARN) {
-		/* This strcpy() is OK, since we know STP_LOG_BUF_LEN
-		 * is > sizeof(WARN_STRING). */
-		strcpy (buf, WARN_STRING);
-		start = sizeof(WARN_STRING) - 1;
+		strncpy(buf, WARN_STRING, bytes_avail);
+		start = min(bytes_avail, sizeof(WARN_STRING) - 1);
 	} else if (type == ERROR) {
-		/* This strcpy() is OK, since we know STP_LOG_BUF_LEN
-		 * is > sizeof(ERR_STRING) (which is < sizeof(WARN_STRING). */
-		strcpy (buf, ERR_STRING);
-		start = sizeof(ERR_STRING) - 1;
+		strncpy(buf, ERR_STRING, bytes_avail);
+		start = min(bytes_avail, sizeof(ERR_STRING) - 1);
 	}
 
-	num = vscnprintf (buf + start, STP_LOG_BUF_LEN - start - 1, fmt, args);
+	bytes_avail -= start;
+	if (unlikely(!bytes_avail))
+		goto restore_irqs;
+
+	num = vscnprintf(buf + start, bytes_avail, fmt, args);
 	if (num + start) {
 		if (buf[num + start - 1] != '\n') {
 			buf[num + start] = '\n';
@@ -71,7 +78,8 @@ static void _stp_vlog (enum code type, const char *func, int line, const char *f
 		}
 #endif
 	}
-	put_cpu();
+restore_irqs:
+	local_irq_restore(flags);
 }
 
 /** Prints warning.
diff --git a/runtime/linux/print.c b/runtime/linux/print.c
index 777bca8b0..1b7864d55 100644
--- a/runtime/linux/print.c
+++ b/runtime/linux/print.c
@@ -35,84 +35,133 @@
  * @{
  */
 
-typedef struct __stp_pbuf {
-	uint32_t len;			/* bytes used in the buffer */
+struct _stp_log {
+	unsigned int len; /* Bytes used in the buffer */
 	char buf[STP_BUFFER_SIZE];
-} _stp_pbuf;
+	struct work_struct flush_work;
+};
 
-static void *Stp_pbuf = NULL;
+static struct _stp_log *_stp_log_pcpu;
+static STP_DEFINE_RWLOCK(_stp_log_flush_lock);
+static atomic_t _stp_log_stop = ATOMIC_INIT(0);
 
-/** private buffer for _stp_vlog() */
-#ifndef STP_LOG_BUF_LEN
-#define STP_LOG_BUF_LEN 256
-#endif
-
-typedef char _stp_lbuf[STP_LOG_BUF_LEN];
-static void *Stp_lbuf = NULL;
+#include "print_flush.c"
+static void _stp_print_flush_worker(struct work_struct *work)
+{
+	/*
+	 * Don't need to worry about raw_smp_processor_id() being unstable while
+	 * preemption is still enabled because this worker was scheduled onto a
+	 * specific CPU and thus won't be migrated.
+	 */
+	struct _stp_log *log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+
+	/*
+	 * Interrupts need to be disabled when flushing the print buffer because
+	 * the buffer could get modified if a print is used inside an interrupt.
+	 */
+	local_irq_disable();
+	__stp_print_flush(log);
+	local_irq_enable();
+}
 
 /* create percpu print and io buffers */
 static int _stp_print_init (void)
 {
-	Stp_pbuf = _stp_alloc_percpu(sizeof(_stp_pbuf));
-	if (unlikely(Stp_pbuf == 0))
-		return -1;
-
-	/* now initialize IO buffer used in io.c */
-	Stp_lbuf = _stp_alloc_percpu(sizeof(_stp_lbuf));
-	if (unlikely(Stp_lbuf == 0)) {
-		_stp_free_percpu(Stp_pbuf);
-		return -1;
+	unsigned int cpu;
+
+	_stp_log_pcpu = _stp_alloc_percpu(sizeof(*_stp_log_pcpu));
+	if (!_stp_log_pcpu)
+		return -ENOMEM;
+
+	for_each_possible_cpu(cpu) {
+		struct _stp_log *log = per_cpu_ptr(_stp_log_pcpu, cpu);
+
+		INIT_WORK(&log->flush_work, _stp_print_flush_worker);
 	}
 	return 0;
 }
 
 static void _stp_print_cleanup (void)
 {
-	if (Stp_pbuf)
-		_stp_free_percpu(Stp_pbuf);
-	if (Stp_lbuf)
-		_stp_free_percpu(Stp_lbuf);
-}
+	unsigned long flags;
+	unsigned int cpu;
+
+	/*
+	 * Wait for all the loggers to finish scheduling their flush workers so
+	 * we can flush them all and ensure that none of them will be running or
+	 * will start up again after this function returns.
+	 */
+	atomic_set(&_stp_log_stop, 1);
+	stp_write_lock_irqsave(&_stp_log_flush_lock, flags);
+	stp_write_unlock_irqrestore(&_stp_log_flush_lock, flags);
+
+	/* Wait for all the flush workers to finish */
+	for_each_possible_cpu(cpu) {
+		struct _stp_log *log = per_cpu_ptr(_stp_log_pcpu, cpu);
+
+		flush_work(&log->flush_work);
+	}
 
-#include "print_flush.c"
+	_stp_free_percpu(_stp_log_pcpu);
+}
 
 static inline void _stp_print_flush(void)
 {
-	stp_print_flush(per_cpu_ptr(Stp_pbuf, smp_processor_id()));
+	struct _stp_log *log;
+	unsigned int cpu;
+
+	if (atomic_read(&_stp_log_stop))
+		return;
+
+	/*
+	 * The write lock is never acquired inside an interrupt so we don't need
+	 * to disable interrupts while holding the read lock.
+	 */
+	read_lock(&_stp_log_flush_lock);
+	if (!atomic_read(&_stp_log_stop)) {
+		cpu = raw_smp_processor_id();
+		log = per_cpu_ptr(_stp_log_pcpu, cpu);
+		schedule_work_on(cpu, &log->flush_work);
+	}
+	read_unlock(&_stp_log_flush_lock);
 }
 #ifndef STP_MAXBINARYARGS
 #define STP_MAXBINARYARGS 127
 #endif
 
 
-/** Reserves space in the output buffer for direct I/O.
+/** Reserves space in the output buffer for direct I/O. Must be called with IRQs
+ *  disabled.
  */
 static void * _stp_reserve_bytes (int numbytes)
 {
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
-	int size = STP_BUFFER_SIZE - pb->len;
-	void * ret;
+	struct _stp_log *log;
+	char *ret = NULL;
 
 	if (unlikely(numbytes == 0 || numbytes > STP_BUFFER_SIZE))
 		return NULL;
 
-	if (unlikely(numbytes > size))
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	if (unlikely(numbytes > (STP_BUFFER_SIZE - log->len))) {
 		_stp_print_flush();
-
-	ret = pb->buf + pb->len;
-	pb->len += numbytes;
+	} else {
+		ret = &log->buf[log->len];
+		log->len += numbytes;
+	}
 	return ret;
 }
 
 
 static void _stp_unreserve_bytes (int numbytes)
 {
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
+	struct _stp_log *log;
 
-	if (unlikely(numbytes == 0 || numbytes > pb->len))
+	if (unlikely(numbytes == 0))
 		return;
 
-	pb->len -= numbytes;
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	if (numbytes <= log->len)
+		log->len -= numbytes;
 }
 
 /** Write 64-bit args directly into the output stream.
@@ -123,6 +172,7 @@ static void _stp_unreserve_bytes (int numbytes)
  */
 static void _stp_print_binary (int num, ...)
 {
+	unsigned long flags;
 	va_list vargs;
 	int i;
 	int64_t *args;
@@ -130,6 +180,7 @@ static void _stp_print_binary (int num, ...)
 	if (unlikely(num > STP_MAXBINARYARGS))
 		num = STP_MAXBINARYARGS;
 
+	local_irq_save(flags);
 	args = _stp_reserve_bytes(num * sizeof(int64_t));
 
 	if (likely(args != NULL)) {
@@ -139,6 +190,7 @@ static void _stp_print_binary (int num, ...)
 		}
 		va_end(vargs);
 	}
+	local_irq_restore(flags);
 }
 
 /** Print into the print buffer.
@@ -160,37 +212,34 @@ static void _stp_printf (const char *fmt, ...)
 
 static void _stp_print (const char *str)
 {
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
-	char *end = pb->buf + STP_BUFFER_SIZE;
-	char *ptr = pb->buf + pb->len;
-	char *instr = (char *)str;
-
-	while (ptr < end && *instr)
-		*ptr++ = *instr++;
-
-	/* Did loop terminate due to lack of buffer space? */
-	if (unlikely(*instr)) {
-		/* Don't break strings across subbufs. */
-		/* Restart after flushing. */
+	struct _stp_log *log;
+	unsigned long flags;
+	unsigned int i;
+
+	local_irq_save(flags);
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	for (i = log->len; i < STP_BUFFER_SIZE && *str; i++)
+		log->buf[i] = *str++;
+	log->len = i;
+
+	/* Flush if the log buffer ran out of space */
+	if (*str)
 		_stp_print_flush();
-		end = pb->buf + STP_BUFFER_SIZE;
-		ptr = pb->buf + pb->len;
-		instr = (char *)str;
-		while (ptr < end && *instr)
-			*ptr++ = *instr++;
-	}
-	pb->len = ptr - pb->buf;
+	local_irq_restore(flags);
 }
 
 static void _stp_print_char (const char c)
 {
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
-	int size = STP_BUFFER_SIZE - pb->len;
-	if (unlikely(1 >= size))
+	struct _stp_log *log;
+	unsigned long flags;
+
+	local_irq_save(flags);
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	if (log->len < STP_BUFFER_SIZE)
+		log->buf[log->len++] = c;
+	else
 		_stp_print_flush();
-	
-	pb->buf[pb->len] = c;
-	pb->len ++;
+	local_irq_restore(flags);
 }
 
 static void _stp_print_kernel_info(char *sname, char *vstr, int ctx, int num_probes)
diff --git a/runtime/print_flush.c b/runtime/print_flush.c
index cf40a2645..0215fba74 100644
--- a/runtime/print_flush.c
+++ b/runtime/print_flush.c
@@ -13,40 +13,32 @@
  * is filled, or this is called. This MUST be called before returning
  * from a probe or accumulated output in the print buffer will be lost.
  *
- * @note Preemption must be disabled to use this.
+ * @note Interrupts must be disabled to use this, and this cannot be used from
+ * interrupt context. Use _stp_print_flush() instead.
  */
 
-static STP_DEFINE_SPINLOCK(_stp_print_lock);
-
-void stp_print_flush(_stp_pbuf *pb)
+void __stp_print_flush(struct _stp_log *log)
 {
-	size_t len = pb->len;
+	size_t len = log->len;
 	void *entry = NULL;
 
 	/* check to see if there is anything in the buffer */
 	if (likely(len == 0))
 		return;
 
-	pb->len = 0;
-
-	if (unlikely(_stp_transport_get_state() != STP_TRANSPORT_RUNNING))
-		return;
+	log->len = 0;
 
 	dbug_trans(1, "len = %zu\n", len);
 
 #ifdef STP_BULKMODE
 #ifdef NO_PERCPU_HEADERS
 	{
-		struct context* __restrict__ c = NULL;
-		char *bufp = pb->buf;
+		char *bufp = log->buf;
 		int inode_locked;
 
-		c = _stp_runtime_entryfn_get_context();
-
 		if (!(inode_locked = _stp_transport_trylock_relay_inode())) {
 			atomic_inc (&_stp_transport_failures);
 #ifndef STP_TRANSPORT_RISKY
-			_stp_runtime_entryfn_put_context(c);
 			return;
 #endif
 		}
@@ -70,26 +62,20 @@ void stp_print_flush(_stp_pbuf *pb)
 
 		if (inode_locked)
 			_stp_transport_unlock_relay_inode();
-
-		_stp_runtime_entryfn_put_context(c);
 	}
 
 #else  /* !NO_PERCPU_HEADERS */
 
 	{
-		struct context* __restrict__ c = NULL;
-		char *bufp = pb->buf;
+		char *bufp = log->buf;
 		struct _stp_trace t = {	.sequence = _stp_seq_inc(),
 					.pdu_len = len};
 		size_t bytes_reserved;
 		int inode_locked;
 
-		c = _stp_runtime_entryfn_get_context();
-
 		if (!(inode_locked = _stp_transport_trylock_relay_inode())) {
 			atomic_inc (&_stp_transport_failures);
 #ifndef STP_TRANSPORT_RISKY
-			_stp_runtime_entryfn_put_context(c);
 			return;
 #endif
 		}
@@ -124,48 +110,24 @@ void stp_print_flush(_stp_pbuf *pb)
 
 		if (inode_locked)
 			_stp_transport_unlock_relay_inode();
-
-		_stp_runtime_entryfn_put_context(c);
 	}
 #endif /* !NO_PERCPU_HEADERS */
 
 #else  /* !STP_BULKMODE */
 
 	{
-		unsigned long flags;
-		struct context* __restrict__ c = NULL;
-		char *bufp = pb->buf;
+		char *bufp = log->buf;
 		int inode_locked;
 
-		/* Prevent probe reentrancy on _stp_print_lock.
-		 *
-		 * Since stp_print_flush may be called from probe context, we
-		 * have to make sure that its lock, _stp_print_lock, can't
-		 * possibly be held outside probe context too.  We ensure this
-		 * by grabbing the context here, so any probe triggered by this
-		 * region will appear reentrant and be skipped rather than
-		 * deadlock.  Failure to get_context just means we're already
-		 * in a probe, which is fine.
-		 *
-		 * (see also _stp_ctl_send for a similar situation)
-                 *
-                 * A better solution would be to replace this
-                 * concurrency-control-laden effort with a lockless
-                 * algorithm.
-		 */
-		c = _stp_runtime_entryfn_get_context();
-
 		if (!(inode_locked = _stp_transport_trylock_relay_inode())) {
 			atomic_inc (&_stp_transport_failures);
 #ifndef STP_TRANSPORT_RISKY
 			dbug_trans(0, "discarding %zu bytes of data\n", len);
-			_stp_runtime_entryfn_put_context(c);
 			return;
 #endif
 		}
 
 		dbug_trans(1, "calling _stp_data_write...\n");
-		stp_spin_lock_irqsave(&_stp_print_lock, flags);
 		while (len > 0) {
 			size_t bytes_reserved;
 
@@ -182,12 +144,9 @@ void stp_print_flush(_stp_pbuf *pb)
 			    break;
 			}
 		}
-		stp_spin_unlock_irqrestore(&_stp_print_lock, flags);
 
 		if (inode_locked)
 			_stp_transport_unlock_relay_inode();
-
-		_stp_runtime_entryfn_put_context(c);
 	}
 #endif /* !STP_BULKMODE */
 }
diff --git a/runtime/stack.c b/runtime/stack.c
index 241ccf793..937e17ccb 100644
--- a/runtime/stack.c
+++ b/runtime/stack.c
@@ -690,13 +690,18 @@ static void _stp_stack_kernel_sprint(char *str, int size, struct context* c,
 	 * then call _stp_stack_print,
 	 * then copy the result into the output string
 	 * and clear the print buffer. */
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
+	struct _stp_log *log;
+	unsigned long flags;
+
+	local_irq_save(flags);
 	_stp_print_flush();
 
 	_stp_stack_kernel_print(c, sym_flags);
 
-	strlcpy(str, pb->buf, size < (int)pb->len ? size : (int)pb->len);
-	pb->len = 0;
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	strlcpy(str, log->buf, size < log->len ? size : log->len);
+	log->len = 0;
+	local_irq_restore(flags);
 }
 
 static void _stp_stack_user_sprint(char *str, int size, struct context* c,
@@ -707,13 +712,18 @@ static void _stp_stack_user_sprint(char *str, int size, struct context* c,
 	 * then call _stp_stack_print,
 	 * then copy the result into the output string
 	 * and clear the print buffer. */
-	_stp_pbuf *pb = per_cpu_ptr(Stp_pbuf, smp_processor_id());
+	struct _stp_log *log;
+	unsigned long flags;
+
+	local_irq_save(flags);
 	_stp_print_flush();
 
 	_stp_stack_user_print(c, sym_flags);
 
-	strlcpy(str, pb->buf, size < (int)pb->len ? size : (int)pb->len);
-	pb->len = 0;
+	log = per_cpu_ptr(_stp_log_pcpu, raw_smp_processor_id());
+	strlcpy(str, log->buf, size < log->len ? size : log->len);
+	log->len = 0;
+	local_irq_restore(flags);
 }
 
 #endif /* _STACK_C_ */
diff --git a/runtime/transport/transport.c b/runtime/transport/transport.c
index bb4a98bd3..aebd7e914 100644
--- a/runtime/transport/transport.c
+++ b/runtime/transport/transport.c
@@ -534,8 +534,14 @@ static void _stp_transport_close(void)
 		   current->pid);
 	_stp_cleanup_and_exit(0);
 	_stp_unregister_ctl_channel();
+
+	/*
+	 * Print cleanup needs to be done before the transport is closed because
+	 * the print driver uses a worker to asynchronously send data via the
+	 * transport.
+	 */
+	_stp_print_cleanup();
 	_stp_transport_fs_close();
-	_stp_print_cleanup();	/* free print buffers */
 	_stp_mem_debug_done();
 
 	dbug_trans(1, "---- CLOSED ----\n");
diff --git a/runtime/vsprintf.c b/runtime/vsprintf.c
index 28fd18f16..a08c2b264 100644
--- a/runtime/vsprintf.c
+++ b/runtime/vsprintf.c
@@ -542,6 +542,8 @@ _stp_vsnprintf(char *buf, size_t size, const char *fmt, va_list args)
 				   number of chars for from string */
 	int qualifier;		/* 'h', 'l', or 'L' for integer fields */
 	int num_bytes = 0;
+	unsigned long irqflags = 0;
+	bool disabled_irqs = false;
 
 	/* Reject out-of-range values early */
 	if (unlikely((int) size < 0))
@@ -724,11 +726,14 @@ _stp_vsnprintf(char *buf, size_t size, const char *fmt, va_list args)
 	    num_bytes = STP_BUFFER_SIZE;
 	  }
 
+	  local_irq_save(irqflags);
 	  str = (char*)_stp_reserve_bytes(num_bytes);
 	  if (str == NULL) {
+	    local_irq_restore(irqflags);
 	    _stp_error("Couldn't reserve any print buffer space\n");
 	    return 0;
 	  }
+	  disabled_irqs = true;
 	  size = num_bytes;
 	  end = str + size - 1;
 
@@ -820,8 +825,10 @@ _stp_vsnprintf(char *buf, size_t size, const char *fmt, va_list args)
 					field_width, precision,
 					*fmt, flags);
 			if (unlikely(str == NULL)) {
-				if (num_bytes > 0)
+				if (num_bytes > 0) {
 					_stp_unreserve_bytes(num_bytes);
+					local_irq_restore(irqflags);
+				}
 				return 0;
 			}
 			continue;
@@ -923,6 +930,9 @@ _stp_vsnprintf(char *buf, size_t size, const char *fmt, va_list args)
                   /* don't write out a null byte if the buf size is zero */
                   *end = '\0';
 	}
+
+	if (disabled_irqs)
+		local_irq_restore(irqflags);
 	return str-buf;
 }
 
diff --git a/translate.cxx b/translate.cxx
index 53f1d0725..a372189b6 100644
--- a/translate.cxx
+++ b/translate.cxx
@@ -1354,6 +1354,9 @@ c_unparser::emit_compiled_printfs ()
       o->newline() << "unsigned long ptr_value;";
       o->newline() << "int num_bytes;";
 
+      if (print_to_stream)
+	  o->newline() << "unsigned long irqflags;";
+
       o->newline() << "(void) width;";
       o->newline() << "(void) precision;";
       o->newline() << "(void) ptr_value;";
@@ -1452,6 +1455,7 @@ c_unparser::emit_compiled_printfs ()
 	    }
 
 	  o->newline() << "num_bytes = clamp(num_bytes, 0, STP_BUFFER_SIZE);";
+	  o->newline() << "local_irq_save(irqflags);";
 	  o->newline() << "str = (char*)_stp_reserve_bytes(num_bytes);";
 	  o->newline() << "end = str ? str + num_bytes - 1 : 0;";
         }
@@ -1548,7 +1552,7 @@ c_unparser::emit_compiled_printfs ()
 	      o->indent(1);
 	      if (print_to_stream)
 		  o->newline() << "_stp_unreserve_bytes(num_bytes);";
-	      o->newline() << "return;";
+	      o->newline() << "goto exit;";
 	      o->newline(-1) << "}";
 	      break;
 
@@ -1575,7 +1579,10 @@ c_unparser::emit_compiled_printfs ()
 
       o->newline(-1) << "}";
 
-      o->newline(-1) << "}";
+      o->newline(-1) << "exit:";
+      if (print_to_stream)
+	  o->newline() << "local_irq_restore(irqflags);";
+      o->newline() << "}";
     }
   o->newline() << "#endif // STP_LEGACY_PRINT";
 }
-- 
2.29.2