Skip to contentSkip to conversation

trace_printk() support in trace-cmd

DISCUSSION Avi Kivity 4 participants 27 messages Nov 15, 2010 – Dec 16, 2010

Subsystems (3)
x86 KVM KVM x86
lore
Share & tools
lore

Avi Kivity

author
#0 lore raw

trace-cmd doesn't like trace_printk():

<...>-23775 [000] 26343.288803: kvm_emulate_insn: 0:f14e9: rep insb
<...>-23775 [000] 26343.288804: bprint: x86_emulate_insn : (NO FORMAT FOUND at ffffffffa0131460)

<...>-23775 [000] 26343.288807: bprint: x86_emulate_insn : (NO FORMAT FOUND at ffffffffa0131460)

any chance to get it to work with custom printks?

I guess I should use 'perf probe' instead.

Signature · 1 line
error compiling committee.c: too many arguments to function
#1 lore raw
Quoted 6 lines · Avi Kivity

trace-cmd doesn't like trace_printk():

<...>-23775 [000] 26343.288803: kvm_emulate_insn: 0:f14e9: rep insb
<...>-23775 [000] 26343.288804: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

Quoted 7 lines

<...>-23775 [000] 26343.288807: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

any chance to get it to work with custom printks?

I guess I should use 'perf probe' instead.

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

-- Steve

author
#2 lore raw
Quoted 10 lines · Steven Rostedt
Quoted 9 lines · Avi Kivity

trace-cmd doesn't like trace_printk():

<...>-23775 [000] 26343.288803: kvm_emulate_insn: 0:f14e9: rep insb
<...>-23775 [000] 26343.288804: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

<...>-23775 [000] 26343.288807: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

Quoted 7 lines
Quoted 4 lines

any chance to get it to work with custom printks?

I guess I should use 'perf probe' instead.

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

kernel 2.6.37-rc1+, I think latest trace-cmd; will retry.

Meanwhile 'perf probe' grumbles on anonymous unions:

Quoted 3 lines

src(tyep:operand) has no member val.
Failed to find 'ctxt' in this function.
Error: Failed to add events. (-22)

For

--add 'insb=arch/x86/kvm/emulate.c:3369 insn=ctxt->decode.b bytes=ctxt->decode.dst.bytes port=ctxt->decode.src.val cx=ctxt->decode.regs[1] di=ctxt->decode.regs[7] addr=ctxt->decode.dst.mem.addr cpos=ctxt->decode.io_read.pos cend=ctxt->decode.io_read.end'

(ctxt->decode.src.val is a member of an anonymous union in ctxt->decode.src, which is of type 'struct operand')

Signature · 1 line
error compiling committee.c: too many arguments to function
#3 lore raw
Quoted 6 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

kernel 2.6.37-rc1+, I think latest trace-cmd; will retry.

I'm curious if you had a chance to try yet. If it is still broken I would like to fix it ASAP.

Thanks!

-- Steve

author
#4 lore raw
Quoted 11 lines · Steven Rostedt
Quoted 6 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

kernel 2.6.37-rc1+, I think latest trace-cmd; will retry.

I'm curious if you had a chance to try yet. If it is still broken I would like to fix it ASAP.

Just did, still broken. Fixing it would be greatly appreciated.

Signature · 1 line
error compiling committee.c: too many arguments to function
#5 lore raw
Quoted 7 lines · Avi Kivity
Quoted 6 lines · Steven Rostedt
Quoted 5 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

Quoted 8 lines
Quoted 5 lines
Quoted 1 line

kernel 2.6.37-rc1+, I think latest trace-cmd; will retry.

I'm curious if you had a chance to try yet. If it is still broken I would like to fix it ASAP.

Just did, still broken. Fixing it would be greatly appreciated.

Hmm, I'll try it out on the latest kernel. Would you be able to upload the trace.dat that does not work someplace that I can get it. I'd like to take a look at it. If you don't have a place to put it, I could give you access to my box, and you can scp it there.

Thanks,

-- Steve

#6 lore raw
Quoted 14 lines · Steven Rostedt
Quoted 13 lines · Avi Kivity
Quoted 11 lines · Steven Rostedt
Quoted 6 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

Which kernel are you using, and/or which trace-cmd? It works fine for me. But there has been bugs with older kernels and older trace-cmds.

kernel 2.6.37-rc1+, I think latest trace-cmd; will retry.

I'm curious if you had a chance to try yet. If it is still broken I would like to fix it ASAP.

Quoted 7 lines
Quoted 2 lines

Just did, still broken. Fixing it would be greatly appreciated.

Hmm, I'll try it out on the latest kernel. Would you be able to upload the trace.dat that does not work someplace that I can get it. I'd like to take a look at it. If you don't have a place to put it, I could give you access to my box, and you can scp it there.

Hmm, I still can not reproduce. But as a workaround, here's what you can do for now. Instead of using trace_printk() use:

	__trace_printk(_THIS_IP_, "format", args);

This will force the snprintf into the buffer and skips the bprintk trick to post process at read time.

-- Steve

#14 lore raw
In reply to Avi Kivity
Quoted 10 lines · Avi Kivity

trace-cmd doesn't like trace_printk():

<...>-23775 [000] 26343.288803: kvm_emulate_insn: 0:f14e9: rep insb
<...>-23775 [000] 26343.288804: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

<...>-23775 [000] 26343.288807: bprint: x86_emulate_insn :
(NO FORMAT FOUND at ffffffffa0131460)

any chance to get it to work with custom printks?

BTW, what does /debug/tracing/printk_formats show?

Thanks,

-- Steve

author
#7 lore raw
In reply to Steven Rostedt
Quoted 6 lines · Steven Rostedt
Quoted 5 lines

Hmm, I'll try it out on the latest kernel. Would you be able to upload the trace.dat that does not work someplace that I can get it. I'd like to take a look at it. If you don't have a place to put it, I could give you access to my box, and you can scp it there.

Quoted 8 lines

Hmm, I still can not reproduce. But as a workaround, here's what you can do for now. Instead of using trace_printk() use:

	__trace_printk(_THIS_IP_, "format", args);

This will force the snprintf into the buffer and skips the bprintk trick to post process at read time.

I see a trace_printk() commit in trace-cmd.git. Is that related? If not, I'll work on getting a small sample of the problem.

Signature · 1 line
error compiling committee.c: too many arguments to function
author
#15 lore raw
In reply to Steven Rostedt
Quoted 2 lines · Steven Rostedt

BTW, what does /debug/tracing/printk_formats show?

Empty.

Signature · 1 line
error compiling committee.c: too many arguments to function
#16 lore raw
Quoted 6 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

BTW, what does /debug/tracing/printk_formats show?

Empty.

So you have real trace_printk's not bprintk's?

That is, if the format is not a const, then we fall back to __trace_printk(_THIS_IP_, fmt, args);

And this is a different object. I have not tested these in a while, I'll give it a try.

But if your printks are bprintks, then the bug is in the kernel, since that printk_formats needs to show something.

-- Steve

author
#17 lore raw
Quoted 10 lines · Steven Rostedt
Quoted 6 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

BTW, what does /debug/tracing/printk_formats show?

Empty.

So you have real trace_printk's not bprintk's?

What are bprintk()s?

Quoted 8 lines

That is, if the format is not a const, then we fall back to __trace_printk(_THIS_IP_, fmt, args);

And this is a different object. I have not tested these in a while, I'll give it a try.

But if your printks are bprintks, then the bug is in the kernel, since that printk_formats needs to show something.

What I do is sprinkle trace_printk()s around my code and expect to see them interspersed with enabled tracepoints in 'trace-cmd report'. Is that not the intended behaviour?

Signature · 1 line
error compiling committee.c: too many arguments to function
#18 lore raw
Quoted 6 lines · Avi Kivity
Quoted 5 lines · Steven Rostedt
Quoted 4 lines · Avi Kivity
Quoted 2 lines · Steven Rostedt

BTW, what does /debug/tracing/printk_formats show?

Quoted 7 lines
Quoted 5 lines
Quoted 2 lines

Empty.

So you have real trace_printk's not bprintk's?

What are bprintk()s?

trace_printk() tries to be clever. If it detects that the format is constant, instead of doing the sprintf at the tracepoint, it copies a pointer to the format, and then copies the args to the stack. (although, I'm not sure how much quicker this is). It just saves on the format in the ring buffer.

If the format is not static, then it just simply calls __trace_printk() that does the sprintf() and writes that output into the buffer.

Quoted 7 lines
Quoted 7 lines

That is, if the format is not a const, then we fall back to __trace_printk(_THIS_IP_, fmt, args);

And this is a different object. I have not tested these in a while, I'll give it a try.

Quoted 7 lines
Quoted 2 lines

But if your printks are bprintks, then the bug is in the kernel, since that printk_formats needs to show something.

What I do is sprinkle trace_printk()s around my code and expect to see them interspersed with enabled tracepoints in 'trace-cmd report'. Is that not the intended behaviour?

No, that is exactly the intended behavior. But the problem is, for some reason, the bprintk's (the default that trace_printk() uses) is not having the format exported. Remember, only the pointer to the format is stored in the ring buffer (and thus exported by trace-cmd). If that format is not shown in the printk_format's than trace-cmd has no way to determine what that trace_printk's format was.

I guess the question is, why did it not show up?

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

-- Steve

author
#8 lore raw
In reply to Avi Kivity
Quoted 14 lines · Avi Kivity
Quoted 13 lines · Steven Rostedt
Quoted 2 lines

Hmm, I'll try it out on the latest kernel. Would you be able to

upload

Quoted 1 line

the trace.dat that does not work someplace that I can get it. I'd

like

Quoted 1 line

to take a look at it. If you don't have a place to put it, I could

give

Quoted 1 line

you access to my box, and you can scp it there.

Hmm, I still can not reproduce. But as a workaround, here's what you can do for now. Instead of using trace_printk() use:

Quoted 7 lines
Quoted 4 lines
    __trace_printk(_THIS_IP_, "format", args);

This will force the snprintf into the buffer and skips the bprintk trick to post process at read time.

I see a trace_printk() commit in trace-cmd.git. Is that related? If not, I'll work on getting a small sample of the problem.

Sample: http://people.redhat.com/akivity/trace.dat.bz2

Signature · 1 line
error compiling committee.c: too many arguments to function
author
#19 lore raw
In reply to Steven Rostedt
Quoted 3 lines · Steven Rostedt

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Signature · 1 line
error compiling committee.c: too many arguments to function
#20 lore raw

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

- Arnaldo

author
#21 lore raw
Quoted 10 lines · Arnaldo Carvalho de Melo

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

Signature · 1 line
error compiling committee.c: too many arguments to function
#22 lore raw

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:

Quoted 10 lines · Arnaldo Carvalho de Melo
Quoted 9 lines

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Quoted 7 lines
Quoted 1 line

Can you tell us which functions, environment, etc?

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

I mean the "I tried to use 'perf probe'" part.

- Arnaldo

author
#23 lore raw
Quoted 13 lines · Arnaldo Carvalho de Melo

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:

Quoted 12 lines · Arnaldo Carvalho de Melo
Quoted 10 lines

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

Quoted 7 lines
Quoted 5 lines

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

I mean the "I tried to use 'perf probe'" part.

Well, same, more or less.

perf probe -m kvm --add 'fetch_access=paging64_fetch
pt_access=gw->pt_access pte_access=gw->pte_access dirty'

would return garbage for gw->*, and the log would show the exception handler called. gw is most certainly valid.

Signature · 1 line
error compiling committee.c: too many arguments to function
#24 lore raw
Quoted 20 lines · Avi Kivity
Quoted 19 lines · Arnaldo Carvalho de Melo

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:

Quoted 17 lines · Arnaldo Carvalho de Melo
Quoted 10 lines

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

Quoted 8 lines
Quoted 1 line

I mean the "I tried to use 'perf probe'" part.

Well, same, more or less.

  perf probe -m kvm --add 'fetch_access=paging64_fetch pt_access=gw->pt_access pte_access=gw->pte_access dirty'

would return garbage for gw->*, and the log would show the exception handler called. gw is most certainly valid.

Thank you for reporting.
Hmm, actually, pagefaults could happen on fetching variables. But fetching argument routines should handle it...
I'd like to check it, could you tell me details? for example, that exception log, kprobe-tracer's event definition(you can see it via debugfs/tracing/kprobe-events) and the result of perf probe -L paging64_fetch:0-10.

Best regards,

Signature · 4 lines
Masami HIRAMATSU
2nd Dept. Linux Technology Center
Hitachi, Ltd., Systems Development Laboratory
E-mail: [email protected]
#9 lore raw
In reply to Avi Kivity
Quoted 8 lines · Avi Kivity
Quoted 3 lines · Avi Kivity

I see a trace_printk() commit in trace-cmd.git. Is that related? If not, I'll work on getting a small sample of the problem.

Sample: http://people.redhat.com/akivity/trace.dat.bz2

You said previously that /debug/tracing/printk_formats was empty? This is the problem. It uses this file to map what the format of the printk is to what is being printed. But if we don't have this mapping, trace-cmd (nor perf) can not figure this out.

You are using the latest kernel for this? What's your work flow? Do you load kvm modules after you start the trace, or are they always loaded?

Are the trace_printk's in the core kernel too, and not being printed?

Thanks,

-- Steve

author
#10 lore raw
Quoted 11 lines · Steven Rostedt
Quoted 8 lines · Avi Kivity
Quoted 3 lines · Avi Kivity

I see a trace_printk() commit in trace-cmd.git. Is that related? If not, I'll work on getting a small sample of the problem.

Sample: http://people.redhat.com/akivity/trace.dat.bz2

You said previously that /debug/tracing/printk_formats was empty?

Still the case.

Quoted 6 lines

This
is the problem. It uses this file to map what the format of the printk is to what is being printed. But if we don't have this mapping, trace-cmd (nor perf) can not figure this out.

You are using the latest kernel for this?

2.6.37-rc5 plus a bunch of kvm patches.

Quoted 2 lines

What's your work flow? Do you
load kvm modules after you start the trace, or are they always loaded?

Loaded on boot.

Quoted 1 line

Are the trace_printk's in the core kernel too, and not being printed?

I don't have any trace_printk()s in the core kernel, only in modules. Perhaps module initialization does not communicate trace_printk formats?

Signature · 1 line
error compiling committee.c: too many arguments to function
#11 lore raw
Quoted 4 lines · Avi Kivity
Quoted 2 lines

What's your work flow? Do you
load kvm modules after you start the trace, or are they always loaded?

Loaded on boot.

Via initramfs?

Quoted 5 lines
Quoted 2 lines

Are the trace_printk's in the core kernel too, and not being printed?

I don't have any trace_printk()s in the core kernel, only in modules. Perhaps module initialization does not communicate trace_printk formats?

They should.

Could you send me a patch that has the trace_printk()s you are using.

Thanks,

-- Steve

author
#12 lore raw
Quoted 8 lines · Steven Rostedt
Quoted 4 lines · Avi Kivity
Quoted 2 lines

What's your work flow? Do you
load kvm modules after you start the trace, or are they always loaded?

Loaded on boot.

Via initramfs?

No, regular printks.

Quoted 10 lines
Quoted 5 lines
Quoted 2 lines

Are the trace_printk's in the core kernel too, and not being printed?

I don't have any trace_printk()s in the core kernel, only in modules. Perhaps module initialization does not communicate trace_printk formats?

They should.

Could you send me a patch that has the trace_printk()s you are using.

Attached (with __trace_printk()s, which is what I used).

Signature · 1 line
error compiling committee.c: too many arguments to function
arch/x86/kvm/mmu.c +9 -0
index d75ba1e..df86917 100644
@@ -1449,6 +1449,10 @@ static struct kvm_mmu_page *kvm_mmu_get_page(struct kvm_vcpu *vcpu,
 	if (role.direct)
 		role.cr4_pae = 0;
 	role.access = access;
+	__trace_printk(_THIS_IP_,
+		       "base_role %x access %x role.access %x role %x\n",
+		       vcpu->arch.mmu.base_role, access, role.access,
+		       role.word);
 	if (!vcpu->arch.mmu.direct_map
 	    && vcpu->arch.mmu.root_level <= PT32_ROOT_LEVEL) {
 		quadrant = gaddr >> (PAGE_SHIFT + (PT64_PT_BITS * level));

@@ -1576,6 +1580,11 @@ static void validate_direct_spte(struct kvm_vcpu *vcpu, u64 *sptep,
 		if (child->role.access == direct_access)
 			return;
 
+		__trace_printk(_THIS_IP_,
+			       "child->role %x child->role.access %x direct_access %x\n",
+			       child->role.word, child->role.access,
+			       direct_access);
+
 		mmu_page_remove_parent_pte(child, sptep);
 		__set_spte(sptep, shadow_trap_nonpresent_pte);
 		kvm_flush_remote_tlbs(vcpu->kvm);
arch/x86/kvm/paging_tmpl.h +5 -0
index 4f61fbb..1049729 100644
@@ -450,6 +450,8 @@ static u64 *FNAME(fetch)(struct kvm_vcpu *vcpu, gva_t addr,
 	if (!is_present_gpte(gw->ptes[gw->level - 1]))
 		return NULL;
 
+	__trace_printk(_THIS_IP_, "pt_access %x pte_access %x dirty %d\n",
+		       gw->pt_access, gw->pte_access, dirty);
 	direct_access = gw->pt_access & gw->pte_access;
 	if (!dirty)
 		direct_access &= ~ACC_WRITE_MASK;

@@ -592,6 +594,9 @@ static int FNAME(page_fault)(struct kvm_vcpu *vcpu, gva_t addr, u32 error_code,
 	if (is_error_pfn(pfn))
 		return kvm_handle_bad_page(vcpu->kvm, walker.gfn, pfn);
 
+	__trace_printk(_THIS_IP_, "page_fault: map_writeable %x\n",
+		       map_writable);
+
 	spin_lock(&vcpu->kvm->mmu_lock);
 	if (mmu_notifier_retry(vcpu, mmu_seq))
 		goto out_unlock;
virt/kvm/kvm_main.c +2 -0
index 83f5bf6..05481a3 100644
@@ -1015,6 +1015,8 @@ static pfn_t hva_to_pfn(struct kvm *kvm, unsigned long addr, bool atomic,
 	if (unlikely(npages != 1) && !atomic) {
 		might_sleep();
 
+		__trace_printk(_THIS_IP_, "%s: addr %lx not writeable\n",
+			       __func__, addr);
 		if (writable)
 			*writable = write_fault;
author
#13 lore raw
Quoted 5 lines · Avi Kivity
Quoted 4 lines · Steven Rostedt
Quoted 2 lines · Avi Kivity
Quoted 2 lines

What's your work flow? Do you
load kvm modules after you start the trace, or are they always

Quoted 7 lines
Quoted 5 lines

loaded?

Quoted 2 lines

Loaded on boot.

Via initramfs?

No, regular printks.

Regular modprobe.

Signature · 1 line
error compiling committee.c: too many arguments to function
author
#25 lore raw
In reply to Masami Hiramatsu
Quoted 25 lines · Masami Hiramatsu
Quoted 24 lines · Avi Kivity
Quoted 13 lines · Arnaldo Carvalho de Melo

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:

Quoted 12 lines · Arnaldo Carvalho de Melo
Quoted 10 lines

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

Quoted 7 lines
Quoted 5 lines

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

I mean the "I tried to use 'perf probe'" part.

Well, same, more or less.

Quoted 8 lines
Quoted 4 lines
   perf probe -m kvm --add 'fetch_access=paging64_fetch pt_access=gw->pt_access pte_access=gw->pte_access dirty'

would return garbage for gw->*, and the log would show the exception handler called. gw is most certainly valid.

Thank you for reporting.
Hmm, actually, pagefaults could happen on fetching variables. But fetching argument routines should handle it...

They did handle it (or so I understood from the logs). But they shouldn't have occured in the first place, since gw was dereferenceable (and the function dereferences it). So something went wrong while fetching gw itself (do you interpret the dwarf tables to find where the variable is stored?)

Quoted 3 lines

I'd like to check it, could you tell me details? for example, that exception log, kprobe-tracer's event definition(you can see it via debugfs/tracing/kprobe-events) and the result of perf probe -L paging64_fetch:0-10.

I no longer have the logs, I'll try to reproduce it later.

Signature · 1 line
error compiling committee.c: too many arguments to function
#26 lore raw
Quoted 31 lines · Avi Kivity
Quoted 30 lines · Masami Hiramatsu
Quoted 28 lines · Avi Kivity
Quoted 13 lines · Arnaldo Carvalho de Melo

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:

Quoted 12 lines · Arnaldo Carvalho de Melo
Quoted 10 lines

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:

Quoted 7 lines · Steven Rostedt
Quoted 3 lines

Again, the work around is to replace your trace_printks() with __trace_printk(_THIS_IP_, ...) or just modify the trace_printk() macro in include/linux/kernel.h to always use the __trace_printk() version.

This works; I'm using it for now (I tried to use 'perf probe', but I get unpredictable results, like null pointer derefs).

Can you tell us which functions, environment, etc?

Quoted 7 lines
Quoted 5 lines

Something around 2.6.27-rc4; example functions are FNAME(fetch) in arch/x86/kvm/paging_tmpl.h; compiled modular (which was Steven's guess as to why it fails).

(note, the failure is with trace-cmd, not /sys/kernel/debug/tracing).

I mean the "I tried to use 'perf probe'" part.

Well, same, more or less.

   perf probe -m kvm --add 'fetch_access=paging64_fetch pt_access=gw->pt_access pte_access=gw->pte_access dirty'

would return garbage for gw->*, and the log would show the exception handler called. gw is most certainly valid.

Quoted 6 lines
Quoted 3 lines

Thank you for reporting.
Hmm, actually, pagefaults could happen on fetching variables. But fetching argument routines should handle it...

They did handle it (or so I understood from the logs). But they shouldn't have occured in the first place, since gw was dereferenceable (and the function dereferences it).

Ah, OK. Sometimes, it's hard to find the register/memory location of local variables. (and sometimes it fails)

Quoted 2 lines

So something went wrong while fetching gw itself (do you interpret the
dwarf tables to find where the variable is stored?)

Hm, yes, you can use eu-readelf to dump debuginfo, and also objdump will help you to find the address and assembler code.

Quoted 6 lines
Quoted 4 lines

I'd like to check it, could you tell me details? for example, that exception log, kprobe-tracer's event definition(you can see it via debugfs/tracing/kprobe-events) and the result of perf probe -L paging64_fetch:0-10.

I no longer have the logs, I'll try to reproduce it later.

Oh, Thank you! :)

Signature · 4 lines
Masami HIRAMATSU
2nd Dept. Linux Technology Center
Hitachi, Ltd., Systems Development Laboratory
E-mail: [email protected]