trace_printk() support in trace-cmd

trace_printk() support in trace-cmd

[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?

I guess I should use 'perf probe' instead.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Mon, 2010-11-15 at 19:09 +0200, Avi Kivity wrote:
> 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.
> 

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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/15/2010 07:11 PM, Steven Rostedt wrote:
> On Mon, 2010-11-15 at 19:09 +0200, Avi Kivity wrote:
> >  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.
> >
>
> 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:

> 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')

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Mon, 2010-11-15 at 19:31 +0200, Avi Kivity wrote:
> On 11/15/2010 07:11 PM, Steven Rostedt wrote:

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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/15/2010 08:33 PM, Steven Rostedt wrote:
> On Mon, 2010-11-15 at 19:31 +0200, Avi Kivity wrote:
> >  On 11/15/2010 07:11 PM, Steven Rostedt wrote:
>
> >  >  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.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Tue, 2010-11-16 at 11:19 +0200, Avi Kivity wrote:
> On 11/15/2010 08:33 PM, Steven Rostedt wrote:
> > On Mon, 2010-11-15 at 19:31 +0200, Avi Kivity wrote:
> > >  On 11/15/2010 07:11 PM, Steven Rostedt wrote:
> >
> > >  >  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.
> 

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

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Tue, 2010-11-16 at 08:11 -0500, Steven Rostedt wrote:
> On Tue, 2010-11-16 at 11:19 +0200, Avi Kivity wrote:
> > On 11/15/2010 08:33 PM, Steven Rostedt wrote:
> > > On Mon, 2010-11-15 at 19:31 +0200, Avi Kivity wrote:
> > > >  On 11/15/2010 07:11 PM, Steven Rostedt wrote:
> > >
> > > >  >  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.
> > 
> 
> 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

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Mon, 2010-11-15 at 19:09 +0200, Avi Kivity wrote:
> 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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/16/2010 05:12 PM, Steven Rostedt wrote:
> >
> >  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.

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.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/16/2010 05:13 PM, Steven Rostedt wrote:
> BTW, what does /debug/tracing/printk_formats show?
>

Empty.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Tue, 2010-11-23 at 13:04 +0200, Avi Kivity wrote:
> On 11/16/2010 05:13 PM, Steven Rostedt wrote:
> > 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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/23/2010 04:30 PM, Steven Rostedt wrote:
> On Tue, 2010-11-23 at 13:04 +0200, Avi Kivity wrote:
> >  On 11/16/2010 05:13 PM, Steven Rostedt wrote:
> >  >  BTW, what does /debug/tracing/printk_formats show?
> >  >
> >
> >  Empty.
> >
>
> So you have real trace_printk's not bprintk's?
>

What are 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.

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?

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Tue, 2010-11-23 at 16:37 +0200, Avi Kivity wrote:
> On 11/23/2010 04:30 PM, Steven Rostedt wrote:
> > On Tue, 2010-11-23 at 13:04 +0200, Avi Kivity wrote:
> > >  On 11/16/2010 05:13 PM, Steven Rostedt wrote:
> > >  >  BTW, what does /debug/tracing/printk_formats show?
> > >  >
> > >
> > >  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.

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

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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/23/2010 12:52 PM, Avi Kivity wrote:
> On 11/16/2010 05:12 PM, Steven Rostedt wrote:
>> >
>> >  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.
>
> 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

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> 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).

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Arnaldo Carvalho de Melo]

Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
> On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> >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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
> Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
> >  On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> >  >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).

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Arnaldo Carvalho de Melo]

Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:
> On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
> >Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
> >>  On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> >>  >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).

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

- Arnaldo

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 12/12/2010 07:43 PM, Arnaldo Carvalho de Melo wrote:
> Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:
> >  On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
> >  >Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
> >  >>   On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> >  >>   >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).
>
> 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.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Masami Hiramatsu]

(2010/12/13 2:47), Avi Kivity wrote:
> On 12/12/2010 07:43 PM, Arnaldo Carvalho de Melo wrote:
>> Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:
>> >  On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
>> >  >Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
>> >  >>   On 11/23/2010 05:45 PM, Steven Rostedt wrote:
>> >  >>   >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).
>>
>> 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,

-- 
Masami HIRAMATSU
2nd Dept. Linux Technology Center
Hitachi, Ltd., Systems Development Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Sun, 2010-12-12 at 18:10 +0200, Avi Kivity wrote:
> On 11/23/2010 12:52 PM, Avi Kivity wrote:

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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 12/13/2010 05:26 PM, Steven Rostedt wrote:
> On Sun, 2010-12-12 at 18:10 +0200, Avi Kivity wrote:
> >  On 11/23/2010 12:52 PM, Avi Kivity wrote:
>
> >  >  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.

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

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

Loaded on boot.

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

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Steven Rostedt]

On Mon, 2010-12-13 at 17:43 +0200, Avi Kivity wrote:

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

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

Re: trace_printk() support in trace-cmd

[Avi Kivity]

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

On 12/13/2010 06:28 PM, Steven Rostedt wrote:
> On Mon, 2010-12-13 at 17:43 +0200, Avi Kivity wrote:
>
> >  >    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.

> >
> >  >  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).


-- 
error compiling committee.c: too many arguments to function


[-- Attachment #2: trace-printk.patch --]
[-- Type: text/x-patch, Size: 2400 bytes --]

diff --git a/arch/x86/kvm/mmu.c b/arch/x86/kvm/mmu.c
index d75ba1e..df86917 100644
--- a/arch/x86/kvm/mmu.c
+++ b/arch/x86/kvm/mmu.c
@@ -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);
diff --git a/arch/x86/kvm/paging_tmpl.h b/arch/x86/kvm/paging_tmpl.h
index 4f61fbb..1049729 100644
--- a/arch/x86/kvm/paging_tmpl.h
+++ b/arch/x86/kvm/paging_tmpl.h
@@ -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;
diff --git a/virt/kvm/kvm_main.c b/virt/kvm/kvm_main.c
index 83f5bf6..05481a3 100644
--- a/virt/kvm/kvm_main.c
+++ b/virt/kvm/kvm_main.c
@@ -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;
 

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 12/13/2010 07:05 PM, Avi Kivity wrote:
> On 12/13/2010 06:28 PM, Steven Rostedt wrote:
>> On Mon, 2010-12-13 at 17:43 +0200, Avi Kivity wrote:
>>
>> > >    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.

Regular modprobe.

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Avi Kivity]

On 12/13/2010 01:20 PM, Masami Hiramatsu wrote:
> (2010/12/13 2:47), Avi Kivity wrote:
> >  On 12/12/2010 07:43 PM, Arnaldo Carvalho de Melo wrote:
> >>  Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:
> >>  >   On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
> >>  >   >Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
> >>  >   >>    On 11/23/2010 05:45 PM, Steven Rostedt wrote:
> >>  >   >>    >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).
> >>
> >>  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...

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?)

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

-- 
error compiling committee.c: too many arguments to function

Re: trace_printk() support in trace-cmd

[Masami Hiramatsu]

(2010/12/16 19:20), Avi Kivity wrote:
> On 12/13/2010 01:20 PM, Masami Hiramatsu wrote:
>> (2010/12/13 2:47), Avi Kivity wrote:
>> >  On 12/12/2010 07:43 PM, Arnaldo Carvalho de Melo wrote:
>> >>  Em Sun, Dec 12, 2010 at 07:42:06PM +0200, Avi Kivity escreveu:
>> >>  >   On 12/12/2010 07:36 PM, Arnaldo Carvalho de Melo wrote:
>> >>  >   >Em Sun, Dec 12, 2010 at 06:35:24PM +0200, Avi Kivity escreveu:
>> >>  >   >>    On 11/23/2010 05:45 PM, Steven Rostedt wrote:
>> >>  >   >>    >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).
>> >>
>> >>  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...
> 
> 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)

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

> 
>> 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! :)


-- 
Masami HIRAMATSU
2nd Dept. Linux Technology Center
Hitachi, Ltd., Systems Development Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com