ftrace_init doesn't patch _mcount calls on boot

ftrace_init doesn't patch _mcount calls on boot

[Varad Gautam]

[-- Attachment #1.1.1.1: Type: text/plain, Size: 2291 bytes --]

Hi,

I'm observing the following on qemu with CONFIG_DYNAMIC_FTRACE=y:

root@debian:/sys/kernel/debug/tracing# echo function > current_tracer
[   73.674265] (____ptrval____): expected (00000013 00000013) but got 
(00006097 a38080e7)
[   73.675144] ------------[ ftrace bug ]------------
[   73.675665] ftrace failed to modify
[   73.676548] [<ffffffe000002010>] _stext+0x10/0x3c
[   73.677641]  actual:   97:60:00:00:e7:80:80:a3
[   73.678534] Setting ftrace call site to call ftrace function
[   73.678842] ftrace record flags: 80000001
[   73.679088]  (1)
[   73.679088]  expected tramp: ffffffe000008020
[   73.679687] ------------[ cut here ]------------

This comes from ftrace_check_current_call(), which ensures that the 
patch target location is set to NOPs before patching it with a 
`auipc/jalr MCOUNT_ADDR` sequence when ftrace is enabled 
(ftrace_nop_initialize -> ftrace_init_nop -> ftrace_make_nop -> 
ftrace_check_current_call).

Dumping a few function prologues from memory before enabling ftrace, I 
see that boot-time patching didn't work as expected. The ftrace_stub 
call sequence still exists, which should have been patched over by NOPs.

(gdb) x/10i blk_put_request
    [...]
    0xffffffe0003169ba <blk_put_request+14>:     auipc   ra,0xffcf1
    0xffffffe0003169be <blk_put_request+18>:     jalr    446(ra)

(gdb) disas blk_put_request
Dump of assembler code for function blk_put_request:
    [...]
    0xffffffe0003169ba <+14>:    auipc   ra,0xffcf1
    0xffffffe0003169be <+18>:    jalr    446(ra) # 0xffffffe000007b78 
<ftrace_stub>

Digging further, I find that the copy_to_kernel_nofault() wrapped in 
patch_insn_write() returns without the write going through. Replacing 
this with a memcpy however, makes ftrace work as expected.

I'll be looking into qemu's emulation for copy_to_kernel_nofault() next, 
but I'd like to check if someone else can reproduce this behavior with 
CONFIG_DYNAMIC_FTRACE=y.

Kernel : 
https://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git/commit/?h=for-next&id=7d95a88f9254b711a3a95106fc73f6a3a9866a40

Thanks,
Varad

-- 
SUSE Software Solutions Germany GmbH
Maxfeldstr. 5
90409 Nürnberg
Germany

HRB 36809, AG Nürnberg
Geschäftsführer: Felix Imendörffer

[-- Attachment #1.1.1.2: OpenPGP_0xED23629CC23015F8.asc --]
[-- Type: application/pgp-keys, Size: 6479 bytes --]

[-- Attachment #1.2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

[-- Attachment #2: Type: text/plain, Size: 161 bytes --]

_______________________________________________
linux-riscv mailing list
linux-riscv@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-riscv

Re: ftrace_init doesn't patch _mcount calls on boot

[Atish Patra]

On Tue, Dec 22, 2020 at 2:53 AM Varad Gautam <varad.gautam@suse.com> wrote:
>
> Hi,
>
> I'm observing the following on qemu with CONFIG_DYNAMIC_FTRACE=y:
>
> root@debian:/sys/kernel/debug/tracing# echo function > current_tracer
> [   73.674265] (____ptrval____): expected (00000013 00000013) but got
> (00006097 a38080e7)
> [   73.675144] ------------[ ftrace bug ]------------
> [   73.675665] ftrace failed to modify
> [   73.676548] [<ffffffe000002010>] _stext+0x10/0x3c
> [   73.677641]  actual:   97:60:00:00:e7:80:80:a3
> [   73.678534] Setting ftrace call site to call ftrace function
> [   73.678842] ftrace record flags: 80000001
> [   73.679088]  (1)
> [   73.679088]  expected tramp: ffffffe000008020
> [   73.679687] ------------[ cut here ]------------
>
> This comes from ftrace_check_current_call(), which ensures that the
> patch target location is set to NOPs before patching it with a
> `auipc/jalr MCOUNT_ADDR` sequence when ftrace is enabled
> (ftrace_nop_initialize -> ftrace_init_nop -> ftrace_make_nop ->
> ftrace_check_current_call).
>
> Dumping a few function prologues from memory before enabling ftrace, I
> see that boot-time patching didn't work as expected. The ftrace_stub
> call sequence still exists, which should have been patched over by NOPs.
>
> (gdb) x/10i blk_put_request
>     [...]
>     0xffffffe0003169ba <blk_put_request+14>:     auipc   ra,0xffcf1
>     0xffffffe0003169be <blk_put_request+18>:     jalr    446(ra)
>
> (gdb) disas blk_put_request
> Dump of assembler code for function blk_put_request:
>     [...]
>     0xffffffe0003169ba <+14>:    auipc   ra,0xffcf1
>     0xffffffe0003169be <+18>:    jalr    446(ra) # 0xffffffe000007b78
> <ftrace_stub>
>
> Digging further, I find that the copy_to_kernel_nofault() wrapped in
> patch_insn_write() returns without the write going through. Replacing
> this with a memcpy however, makes ftrace work as expected.
>
> I'll be looking into qemu's emulation for copy_to_kernel_nofault() next,
> but I'd like to check if someone else can reproduce this behavior with
> CONFIG_DYNAMIC_FTRACE=y.
>

Does this fix the issue ?

https://lkml.org/lkml/2020/10/21/77

> Kernel :
> https://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git/commit/?h=for-next&id=7d95a88f9254b711a3a95106fc73f6a3a9866a40
>
> Thanks,
> Varad
>
> --
> SUSE Software Solutions Germany GmbH
> Maxfeldstr. 5
> 90409 Nürnberg
> Germany
>
> HRB 36809, AG Nürnberg
> Geschäftsführer: Felix Imendörffer
> _______________________________________________
> linux-riscv mailing list
> linux-riscv@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-riscv



-- 
Regards,
Atish

_______________________________________________
linux-riscv mailing list
linux-riscv@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-riscv

Re: ftrace_init doesn't patch _mcount calls on boot

[Atish Patra]

On Tue, Dec 22, 2020 at 12:18 PM Atish Patra <atishp@atishpatra.org> wrote:
>
> On Tue, Dec 22, 2020 at 2:53 AM Varad Gautam <varad.gautam@suse.com> wrote:
> >
> > Hi,
> >
> > I'm observing the following on qemu with CONFIG_DYNAMIC_FTRACE=y:
> >
> > root@debian:/sys/kernel/debug/tracing# echo function > current_tracer
> > [   73.674265] (____ptrval____): expected (00000013 00000013) but got
> > (00006097 a38080e7)
> > [   73.675144] ------------[ ftrace bug ]------------
> > [   73.675665] ftrace failed to modify
> > [   73.676548] [<ffffffe000002010>] _stext+0x10/0x3c
> > [   73.677641]  actual:   97:60:00:00:e7:80:80:a3
> > [   73.678534] Setting ftrace call site to call ftrace function
> > [   73.678842] ftrace record flags: 80000001
> > [   73.679088]  (1)
> > [   73.679088]  expected tramp: ffffffe000008020
> > [   73.679687] ------------[ cut here ]------------
> >
> > This comes from ftrace_check_current_call(), which ensures that the
> > patch target location is set to NOPs before patching it with a
> > `auipc/jalr MCOUNT_ADDR` sequence when ftrace is enabled
> > (ftrace_nop_initialize -> ftrace_init_nop -> ftrace_make_nop ->
> > ftrace_check_current_call).
> >
> > Dumping a few function prologues from memory before enabling ftrace, I
> > see that boot-time patching didn't work as expected. The ftrace_stub
> > call sequence still exists, which should have been patched over by NOPs.
> >
> > (gdb) x/10i blk_put_request
> >     [...]
> >     0xffffffe0003169ba <blk_put_request+14>:     auipc   ra,0xffcf1
> >     0xffffffe0003169be <blk_put_request+18>:     jalr    446(ra)
> >
> > (gdb) disas blk_put_request
> > Dump of assembler code for function blk_put_request:
> >     [...]
> >     0xffffffe0003169ba <+14>:    auipc   ra,0xffcf1
> >     0xffffffe0003169be <+18>:    jalr    446(ra) # 0xffffffe000007b78
> > <ftrace_stub>
> >
> > Digging further, I find that the copy_to_kernel_nofault() wrapped in
> > patch_insn_write() returns without the write going through. Replacing
> > this with a memcpy however, makes ftrace work as expected.
> >
> > I'll be looking into qemu's emulation for copy_to_kernel_nofault() next,
> > but I'd like to check if someone else can reproduce this behavior with
> > CONFIG_DYNAMIC_FTRACE=y.
> >
>
> Does this fix the issue ?
>
> https://lkml.org/lkml/2020/10/21/77
>

and this series. It tries to move to fentry from mcount. Guo fixed a
kernel panic in this as well.

https://patchwork.kernel.org/project/linux-riscv/list/?series=403685

> > Kernel :
> > https://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git/commit/?h=for-next&id=7d95a88f9254b711a3a95106fc73f6a3a9866a40
> >
> > Thanks,
> > Varad
> >
> > --
> > SUSE Software Solutions Germany GmbH
> > Maxfeldstr. 5
> > 90409 Nürnberg
> > Germany
> >
> > HRB 36809, AG Nürnberg
> > Geschäftsführer: Felix Imendörffer
> > _______________________________________________
> > linux-riscv mailing list
> > linux-riscv@lists.infradead.org
> > http://lists.infradead.org/mailman/listinfo/linux-riscv
>
>
>
> --
> Regards,
> Atish



-- 
Regards,
Atish

_______________________________________________
linux-riscv mailing list
linux-riscv@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-riscv

Re: ftrace_init doesn't patch _mcount calls on boot

[Varad Gautam]

[-- Attachment #1.1.1.1: Type: text/plain, Size: 3674 bytes --]

On 12/22/20 9:28 PM, Atish Patra wrote:
> On Tue, Dec 22, 2020 at 12:18 PM Atish Patra <atishp@atishpatra.org> wrote:
>>
>> On Tue, Dec 22, 2020 at 2:53 AM Varad Gautam <varad.gautam@suse.com> wrote:
>>>
>>> Hi,
>>>
>>> I'm observing the following on qemu with CONFIG_DYNAMIC_FTRACE=y:
>>>
>>> root@debian:/sys/kernel/debug/tracing# echo function > current_tracer
>>> [   73.674265] (____ptrval____): expected (00000013 00000013) but got
>>> (00006097 a38080e7)
>>> [   73.675144] ------------[ ftrace bug ]------------
>>> [   73.675665] ftrace failed to modify
>>> [   73.676548] [<ffffffe000002010>] _stext+0x10/0x3c
>>> [   73.677641]  actual:   97:60:00:00:e7:80:80:a3
>>> [   73.678534] Setting ftrace call site to call ftrace function
>>> [   73.678842] ftrace record flags: 80000001
>>> [   73.679088]  (1)
>>> [   73.679088]  expected tramp: ffffffe000008020
>>> [   73.679687] ------------[ cut here ]------------
>>>
>>> This comes from ftrace_check_current_call(), which ensures that the
>>> patch target location is set to NOPs before patching it with a
>>> `auipc/jalr MCOUNT_ADDR` sequence when ftrace is enabled
>>> (ftrace_nop_initialize -> ftrace_init_nop -> ftrace_make_nop ->
>>> ftrace_check_current_call).
>>>
>>> Dumping a few function prologues from memory before enabling ftrace, I
>>> see that boot-time patching didn't work as expected. The ftrace_stub
>>> call sequence still exists, which should have been patched over by NOPs.
>>>
>>> (gdb) x/10i blk_put_request
>>>      [...]
>>>      0xffffffe0003169ba <blk_put_request+14>:     auipc   ra,0xffcf1
>>>      0xffffffe0003169be <blk_put_request+18>:     jalr    446(ra)
>>>
>>> (gdb) disas blk_put_request
>>> Dump of assembler code for function blk_put_request:
>>>      [...]
>>>      0xffffffe0003169ba <+14>:    auipc   ra,0xffcf1
>>>      0xffffffe0003169be <+18>:    jalr    446(ra) # 0xffffffe000007b78
>>> <ftrace_stub>
>>>
>>> Digging further, I find that the copy_to_kernel_nofault() wrapped in
>>> patch_insn_write() returns without the write going through. Replacing
>>> this with a memcpy however, makes ftrace work as expected.
>>>
>>> I'll be looking into qemu's emulation for copy_to_kernel_nofault() next,
>>> but I'd like to check if someone else can reproduce this behavior with
>>> CONFIG_DYNAMIC_FTRACE=y.
>>>
>>
>> Does this fix the issue ?
>>
>> https://lkml.org/lkml/2020/10/21/77
>>
> 
> and this series. It tries to move to fentry from mcount. Guo fixed a
> kernel panic in this as well.
> 
> https://patchwork.kernel.org/project/linux-riscv/list/?series=403685
> 

It turned out to be this one [1], which explains why replacing 
copy_to_kernel_nofault with memcpy worked for me. ftrace works for me 
with the current for-next.

[1] 
https://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git/commit/?h=for-next&id=635e3f3e

Regards,
Varad

>>> Kernel :
>>> https://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git/commit/?h=for-next&id=7d95a88f9254b711a3a95106fc73f6a3a9866a40
>>>
>>> Thanks,
>>> Varad
>>>
>>> --
>>> SUSE Software Solutions Germany GmbH
>>> Maxfeldstr. 5
>>> 90409 Nürnberg
>>> Germany
>>>
>>> HRB 36809, AG Nürnberg
>>> Geschäftsführer: Felix Imendörffer
>>> _______________________________________________
>>> linux-riscv mailing list
>>> linux-riscv@lists.infradead.org
>>> http://lists.infradead.org/mailman/listinfo/linux-riscv
>>
>>
>>
>> --
>> Regards,
>> Atish
> 
> 
> 

-- 
SUSE Software Solutions Germany GmbH
Maxfeldstr. 5
90409 Nürnberg
Germany

HRB 36809, AG Nürnberg
Geschäftsführer: Felix Imendörffer

[-- Attachment #1.1.1.2: OpenPGP_0xED23629CC23015F8.asc --]
[-- Type: application/pgp-keys, Size: 6479 bytes --]

[-- Attachment #1.2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

[-- Attachment #2: Type: text/plain, Size: 161 bytes --]

_______________________________________________
linux-riscv mailing list
linux-riscv@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-riscv