[PATCH] itrace spin lock fix

[PATCH] itrace spin lock fix

[Dave Nomura]

[-- Attachment #1: Type: text/plain, Size: 2408 bytes --]

Back in August Frank reported a problem running the itrace test on an 
x86-64 machine.  This was caused by an uninitialized spin_lock and 
possibly by some utrace callouts that didn't need in the spin_lock 
protected regions.  This patch fixes that problem.

> On an RHEL5 x86-64 machine, I got:
>
> BUG: soft lockup - CPU#0 stuck for 10s! [ls_15964:16126]
> CPU 0:
> Modules linked in: stap_7c70ff0a5aa33e45a459d750475957f4_763(U) xt_tcpudp iptable_nat ip_nat ip_conntrack nfnet
> link ip_tables x_tables xfrm_nalgo crypto_api hidp l2cap bluetooth nfs lockd fscache nfs_acl sunrpc dm_multipat
> h video sbs backlight i2c_ec button battery asus_acpi acpi_memhotplug ac lp floppy ata_piix libata scsi_mod i2c
> _piix4 i2c_core pcspkr ide_cd 8139too parport_pc 8139cp mii parport serio_raw cdrom dm_snapshot dm_zero dm_mirr
> or dm_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
> Pid: 16126, comm: ls_15964 Tainted: G      2.6.18-92.1.1.el5 #1
> RIP: 0010:[<ffffffff80064b54>]  [<ffffffff80064b54>] .text.lock.spinlock+0x2/0x30
> RSP: 0018:ffff81001d279dd0  EFLAGS: 00000286
> RAX: 0000000000003efe RBX: ffff8100104b2900 RCX: 0000000000000000
> RDX: ffff8100104b2900 RSI: ffff8100188ee860 RDI: ffffffff883f64c0
> RBP: ffffffff80061e22 R08: ffff81001d278000 R09: 0000000000000001
> R10: ffff810016f059c8 R11: 0000000300000000 R12: 0000000000000282
> R13: a3754e699d64d231 R14: ffff81000563c000 R15: 0000000000003efe
> FS:  0000000000000000(0000) GS:ffffffff8039f000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> CR2: 00007fff904eeaf9 CR3: 000000000dff2000 CR4: 00000000000006e0
>
> Call Trace:
>  [<ffffffff883e137f>] :stap_7c70ff0a5aa33e45a459d750475957f4_763:usr_itrace_init+0x92/0x17d
>  [<ffffffff883e51e8>] :stap_7c70ff0a5aa33e45a459d750475957f4_763:__stp_utrace_attach_match_tsk+0x17c/0x22e
>  [<ffffffff883e52e7>] :stap_7c70ff0a5aa33e45a459d750475957f4_763:__stp_utrace_task_finder_report_exec+0x4d/0x4f
>  [<ffffffff800bd589>] utrace_report_exec+0x58/0x187
>  [<ffffffff8003f49b>] search_binary_handler+0x171/0x26d
>  [<ffffffff8003e950>] do_execve+0x18c/0x243
>  [<ffffffff80054760>] sys_execve+0x36/0x4c
>
>
> This could have been caused by create_itrace_info's use of an
> uninitialized spin_lock.  It is not clear that a spinlock is
> appropriate at all, considering which of the protected calls could
> block.
>
>
> - FChE

-- 
Dave Nomura
LTC Linux Power Toolchain


[-- Attachment #2: itrace_spin_lock.patch --]
[-- Type: text/plain, Size: 2992 bytes --]

diff -paurN old/ChangeLog new/ChangeLog
--- old/ChangeLog	2008-10-22 16:19:10.000000000 -0700
+++ new/ChangeLog	2008-10-22 16:30:32.000000000 -0700
@@ -1,3 +1,7 @@
+2008-10-22  Dave Nomura  <dcnltc@us.ibm.com>
+
+	* runtimes/itrace.c: remove utrace calls from spin_lock regions
+
 2008-10-20	Elliott Baron  <ebaron@redhat.com>
 
 	PR6851
diff -paurN old/runtime/itrace.c new/runtime/itrace.c
--- old/runtime/itrace.c	2008-10-22 16:19:10.000000000 -0700
+++ new/runtime/itrace.c	2008-10-21 14:34:58.000000000 -0700
@@ -137,6 +137,7 @@ static struct itrace_info *create_itrace
 	struct stap_itrace_probe *itrace_probe)
 {
 	struct itrace_info *ui;
+	struct utrace_attached_engine *engine;
 
 	if (debug)
 		printk(KERN_INFO "create_itrace_info: tid=%d\n", tsk->pid);
@@ -151,23 +152,23 @@ static struct itrace_info *create_itrace
 #endif
 	INIT_LIST_HEAD(&ui->link);
 
-	/* push ui onto usr_itrace_info */
-	spin_lock(&itrace_lock);
-	list_add(&ui->link, &usr_itrace_info);
-
 	/* attach a single stepping engine */
-	ui->engine = utrace_attach(ui->tsk, UTRACE_ATTACH_CREATE, &utrace_ops, ui);
-	if (IS_ERR(ui->engine)) {
+	engine = utrace_attach(ui->tsk, UTRACE_ATTACH_CREATE, &utrace_ops, ui);
+	if (IS_ERR(engine)) {
 		printk(KERN_ERR "utrace_attach returns %ld\n",
-			PTR_ERR(ui->engine));
-		ui = NULL;
-	} else {
-		utrace_set_flags(tsk, ui->engine, ui->engine->flags |
-			ui->step_flag |
-			UTRACE_EVENT(CLONE) | UTRACE_EVENT_SIGNAL_ALL |
-			UTRACE_EVENT(DEATH));
+			PTR_ERR(engine));
+		return NULL;
 	}
+
+	/* push ui onto usr_itrace_info */
+	spin_lock(&itrace_lock);
+	list_add(&ui->link, &usr_itrace_info);
 	spin_unlock(&itrace_lock);
+
+	utrace_set_flags(tsk, engine, engine->flags | step_flag |
+		UTRACE_EVENT(CLONE) | UTRACE_EVENT_SIGNAL_ALL |
+		UTRACE_EVENT(DEATH));
+
 	return ui;
 }
 
@@ -192,6 +193,8 @@ int usr_itrace_init(int single_step, pid
 	struct itrace_info *ui;
 	struct task_struct *tsk;
 
+	spin_lock_init(&itrace_lock);
+
 	rcu_read_lock();
 	tsk = find_task_by_pid(tid);
 	if (!tsk) {
@@ -210,11 +213,6 @@ int usr_itrace_init(int single_step, pid
 	put_task_struct(tsk);
 	rcu_read_unlock();
 
-	spin_lock_init(&itrace_lock);
-
-	/* set initial state */
-	spin_lock(&itrace_lock);
-	spin_unlock(&itrace_lock);
 	printk(KERN_INFO "usr_itrace_init: completed for tid = %d\n", tid);
 
 	return 0;
@@ -223,6 +221,8 @@ int usr_itrace_init(int single_step, pid
 void static remove_usr_itrace_info(struct itrace_info *ui)
 {
 	struct itrace_info *tmp;
+	struct task_struct *tsk;
+	struct utrace_attached_engine *engine;
 
 	if (!ui)
 		return;
@@ -231,11 +231,14 @@ void static remove_usr_itrace_info(struc
 		printk(KERN_INFO "remove_usr_itrace_info: tid=%d\n", ui->tid);
 
 	spin_lock(&itrace_lock);
-	if (ui->tsk && ui->engine) {
-		(void) utrace_detach(ui->tsk, ui->engine);
-	}
+	tsk = ui->tsk;
+	engine = ui->engine;
 	list_del(&ui->link);
 	spin_unlock(&itrace_lock);
+
+	if (tsk && engine) {
+		(void) utrace_detach(tsk, engine);
+	}
 	kfree(ui);
 }
 

Re: [PATCH] itrace spin lock fix

[David Smith]

Dave Nomura wrote:
> Back in August Frank reported a problem running the itrace test on an
> x86-64 machine.  This was caused by an uninitialized spin_lock and
> possibly by some utrace callouts that didn't need in the spin_lock
> protected regions.  This patch fixes that problem.

Your patch's ChangeLog is wrong.  You should put the entry in
src/runtime/ChangeLog, not src/ChangeLog.

I ran this patch on a RHEL5 x86_64 (2.6.18-92.1.13.el5debug) machine.
Systemtap couldn't compile modules without the following small patch:

diff --git a/tapsets.cxx b/tapsets.cxx

index bed2796..057a554 100644

--- a/tapsets.cxx

+++ b/tapsets.cxx

@@ -5778,6 +5778,7 @@ itrace_derived_probe_group::emit_module_decls
(systemtap_\
session& s)



   s.op->newline();

   s.op->newline() << "/* ---- itrace probes ---- */";

+  s.op->newline() << "#include \"task_finder.c\"";

   s.op->newline() << "struct stap_itrace_probe {";

   s.op->indent(1);

   s.op->newline() << "struct stap_task_finder_target tgt;";

With the above patch, systemtap could compile modules again.  The
itrace.exp test script ran (with the early exit deleted), but failed
because the itrace probes never got hit.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: [PATCH] itrace spin lock fix

[Dave Nomura]

[-- Attachment #1: Type: text/plain, Size: 1387 bytes --]

I merged your patch in with mine and fixed the ChangeLog entry.

David Smith wrote:
> Dave Nomura wrote:
>   
>> Back in August Frank reported a problem running the itrace test on an
>> x86-64 machine.  This was caused by an uninitialized spin_lock and
>> possibly by some utrace callouts that didn't need in the spin_lock
>> protected regions.  This patch fixes that problem.
>>     
>
> Your patch's ChangeLog is wrong.  You should put the entry in
> src/runtime/ChangeLog, not src/ChangeLog.
>
> I ran this patch on a RHEL5 x86_64 (2.6.18-92.1.13.el5debug) machine.
> Systemtap couldn't compile modules without the following small patch:
>
> diff --git a/tapsets.cxx b/tapsets.cxx
>
> index bed2796..057a554 100644
>
> --- a/tapsets.cxx
>
> +++ b/tapsets.cxx
>
> @@ -5778,6 +5778,7 @@ itrace_derived_probe_group::emit_module_decls
> (systemtap_\
> session& s)
>
>
>
>    s.op->newline();
>
>    s.op->newline() << "/* ---- itrace probes ---- */";
>
> +  s.op->newline() << "#include \"task_finder.c\"";
>
>    s.op->newline() << "struct stap_itrace_probe {";
>
>    s.op->indent(1);
>
>    s.op->newline() << "struct stap_task_finder_target tgt;";
>
> With the above patch, systemtap could compile modules again.  The
> itrace.exp test script ran (with the early exit deleted), but failed
> because the itrace probes never got hit.
>
>   


-- 
Dave Nomura
LTC Linux Power Toolchain


[-- Attachment #2: itrace_spin_lock.patch --]
[-- Type: text/plain, Size: 3562 bytes --]

diff -paurN old/runtime/ChangeLog new/runtime/ChangeLog
--- old/runtime/ChangeLog	2008-10-22 16:19:10.000000000 -0700
+++ new/runtime/ChangeLog	2008-10-24 10:05:58.000000000 -0700
@@ -1,3 +1,7 @@
+2008-10-24  Dave Nomura  <dcnltc@us.ibm.com>
+
+	* itrace.c: remove utrace calls from spin_lock regions
+
 2008-10-17  Wenji Huang  <wenji.huang@oracle.com>
 
 	* task_finder_vma.c (__stp_tf_vma_get_free_entry): Initialize entry.
diff -paurN old/runtime/itrace.c new/runtime/itrace.c
--- old/runtime/itrace.c	2008-10-22 16:19:10.000000000 -0700
+++ new/runtime/itrace.c	2008-10-24 10:04:18.000000000 -0700
@@ -137,6 +137,7 @@ static struct itrace_info *create_itrace
 	struct stap_itrace_probe *itrace_probe)
 {
 	struct itrace_info *ui;
+	struct utrace_attached_engine *engine;
 
 	if (debug)
 		printk(KERN_INFO "create_itrace_info: tid=%d\n", tsk->pid);
@@ -151,23 +152,23 @@ static struct itrace_info *create_itrace
 #endif
 	INIT_LIST_HEAD(&ui->link);
 
-	/* push ui onto usr_itrace_info */
-	spin_lock(&itrace_lock);
-	list_add(&ui->link, &usr_itrace_info);
-
 	/* attach a single stepping engine */
-	ui->engine = utrace_attach(ui->tsk, UTRACE_ATTACH_CREATE, &utrace_ops, ui);
-	if (IS_ERR(ui->engine)) {
+	engine = utrace_attach(ui->tsk, UTRACE_ATTACH_CREATE, &utrace_ops, ui);
+	if (IS_ERR(engine)) {
 		printk(KERN_ERR "utrace_attach returns %ld\n",
-			PTR_ERR(ui->engine));
-		ui = NULL;
-	} else {
-		utrace_set_flags(tsk, ui->engine, ui->engine->flags |
-			ui->step_flag |
-			UTRACE_EVENT(CLONE) | UTRACE_EVENT_SIGNAL_ALL |
-			UTRACE_EVENT(DEATH));
+			PTR_ERR(engine));
+		return NULL;
 	}
+
+	/* push ui onto usr_itrace_info */
+	spin_lock(&itrace_lock);
+	list_add(&ui->link, &usr_itrace_info);
 	spin_unlock(&itrace_lock);
+
+	utrace_set_flags(tsk, engine, engine->flags | step_flag |
+		UTRACE_EVENT(CLONE) | UTRACE_EVENT_SIGNAL_ALL |
+		UTRACE_EVENT(DEATH));
+
 	return ui;
 }
 
@@ -192,6 +193,8 @@ int usr_itrace_init(int single_step, pid
 	struct itrace_info *ui;
 	struct task_struct *tsk;
 
+	spin_lock_init(&itrace_lock);
+
 	rcu_read_lock();
 	tsk = find_task_by_pid(tid);
 	if (!tsk) {
@@ -210,11 +213,6 @@ int usr_itrace_init(int single_step, pid
 	put_task_struct(tsk);
 	rcu_read_unlock();
 
-	spin_lock_init(&itrace_lock);
-
-	/* set initial state */
-	spin_lock(&itrace_lock);
-	spin_unlock(&itrace_lock);
 	printk(KERN_INFO "usr_itrace_init: completed for tid = %d\n", tid);
 
 	return 0;
@@ -223,6 +221,8 @@ int usr_itrace_init(int single_step, pid
 void static remove_usr_itrace_info(struct itrace_info *ui)
 {
 	struct itrace_info *tmp;
+	struct task_struct *tsk;
+	struct utrace_attached_engine *engine;
 
 	if (!ui)
 		return;
@@ -231,11 +231,14 @@ void static remove_usr_itrace_info(struc
 		printk(KERN_INFO "remove_usr_itrace_info: tid=%d\n", ui->tid);
 
 	spin_lock(&itrace_lock);
-	if (ui->tsk && ui->engine) {
-		(void) utrace_detach(ui->tsk, ui->engine);
-	}
+	tsk = ui->tsk;
+	engine = ui->engine;
 	list_del(&ui->link);
 	spin_unlock(&itrace_lock);
+
+	if (tsk && engine) {
+		(void) utrace_detach(tsk, engine);
+	}
 	kfree(ui);
 }
 
diff -paurN old/tapsets.cxx new/tapsets.cxx
--- old/tapsets.cxx	2008-10-24 10:23:22.000000000 -0700
+++ new/tapsets.cxx	2008-10-24 10:27:04.000000000 -0700
@@ -5780,6 +5780,7 @@ itrace_derived_probe_group::emit_module_
 
   s.op->newline();
   s.op->newline() << "/* ---- itrace probes ---- */";
+  s.op->newline() << "#include \"task_finder.c\"";
   s.op->newline() << "struct stap_itrace_probe {";
   s.op->indent(1);
   s.op->newline() << "struct stap_task_finder_target tgt;";

Re: [PATCH] itrace spin lock fix

[David Smith]

Dave Nomura wrote:
I merged your patch in with mine and fixed the ChangeLog entry.

Great, but...

>> With the above patch, systemtap could compile modules again.  The
>> itrace.exp test script ran (with the early exit deleted), but failed
>> because the itrace probes never got hit.

Shouldn't the itrace probes have been hit?

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: [PATCH] itrace spin lock fix

[Dave Nomura]

Sorry, I forgot about that.  The probe used to fire  because Frank had 
to disable the test because it was crashing.  I'm not sure what has 
changed that is preventing the itrace probe from firing.  I experimented 
a bit and found that if I added a uprobe that didn't do anything related 
to the itrace probe, then the itrace probe would fire.  This is going to 
take further study.  Any ideas on what might have changed?

David Smith wrote:
> Dave Nomura wrote:
> I merged your patch in with mine and fixed the ChangeLog entry.
>
> Great, but...
>
>   
>>> With the above patch, systemtap could compile modules again.  The
>>> itrace.exp test script ran (with the early exit deleted), but failed
>>> because the itrace probes never got hit.
>>>       
>
> Shouldn't the itrace probes have been hit?
>
>   

Re: [PATCH] itrace spin lock fix

[David Smith]

Dave Nomura wrote:
> Sorry, I forgot about that.  The probe used to fire  because Frank had
> to disable the test because it was crashing.  I'm not sure what has
> changed that is preventing the itrace probe from firing.  I experimented
> a bit and found that if I added a uprobe that didn't do anything related
> to the itrace probe, then the itrace probe would fire.  This is going to
> take further study.  Any ideas on what might have changed?

I'm afraid you question is a bit too broad for me to answer.  As far as
the task_finder goes, some internals have changed to support the new
version of utrace, but the external interface hasn't changed.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: [PATCH] itrace spin lock fix

[Maynard Johnson]

David Smith wrote:
> Dave Nomura wrote:
>> Sorry, I forgot about that.  The probe used to fire  because Frank had
>> to disable the test because it was crashing.  I'm not sure what has
>> changed that is preventing the itrace probe from firing.  I experimented
>> a bit and found that if I added a uprobe that didn't do anything related
>> to the itrace probe, then the itrace probe would fire.  This is going to
>> take further study.  Any ideas on what might have changed?
> 
> I'm afraid you question is a bit too broad for me to answer.  As far as
> the task_finder goes, some internals have changed to support the new
> version of utrace, but the external interface hasn't changed.
FYI . . . Dave is no longer available to work on this task, so I'll be taking it 
over.  It will take me some time to come up to speed.  I just didn't want you 
all to think that this patch submission was being dropped or neglected.

Thanks.
-Maynard Johnson
>