Re: Failure in syscall.open probe

[Arkady <arkady dot miasnikov at gmail dot com>]

Update 4
The problem can be reproduced on the kernel
2.6.32-696.10.1.el6.x86_64 #1 SMP as well

On Fri, Aug 25, 2017 at 6:55 AM, Arkady <arkady.miasnikov@gmail.com> wrote:
> Update 3
>
> This code fails as well
>
>
> global ARRAY_FILENAME%
>
> probe syscall.open
> {
>   tid = tid()
>   ARRAY_FILENAME[tid] = filename
> }
>
> probe syscall.open.return
> {
>   tid = tid();
>   delete ARRAY_FILENAME[tid]
> }
>
> Load thescript
> stap -g -p 4 -m test_open  -v -k test_open.stp
> staprun test_open -L
>
> Run a tight loop which opens a file
> touch test.txt;while [ 1 ];do cat test.txt;done;
>
> Wait a couple of minutes.
>
> The problem appears to be specific for the kernel
> 2.6.32-696.3.2.el6.x86_64 #1 CentOS 6.9
>
> On Thu, Aug 24, 2017 at 7:28 PM, Arkady <arkady.miasnikov@gmail.com> wrote:
>> Update 2
>>
>> I made the script shorter - failed after 400 driver restarts
>>
>> global ARRAY_FILENAME_PID%
>> global ARRAY_TIMESTAMP_OPEN%
>>
>> function current_time:long()
>> %{  /* pure */
>>    struct timespec now = current_kernel_time();
>>    STAP_RETURN(timespec_to_ns(&now));
>> %}
>>
>> probe syscall.open
>> {
>>    tid = tid()
>>    ARRAY_FILENAME_PID[tid] = filename
>>    ARRAY_TIMESTAMP_OPEN[tid] = current_time()
>> }
>>
>> probe syscall.open.return
>> {
>>    tid = tid();
>>    delete ARRAY_FILENAME_PID[tid]
>>    delete ARRAY_TIMESTAMP_OPEN[tid]
>> }
>>
>> On Thu, Aug 24, 2017 at 5:35 PM, Arkady <arkady.miasnikov@gmail.com> wrote:
>>> Update
>>> The build line can be as short as
>>>
>>> stap -g -p4 -m test_open  -v -k test_open.stp
>>>
>>>
>>> On Thu, Aug 24, 2017 at 5:26 PM, Arkady <arkady.miasnikov@gmail.com> wrote:
>>>> Hi,
>>>>
>>>> I am trying the following code
>>>> https://gist.github.com/larytet/5c361b1a4ee967655f500909026978f9
>>>> - the script is mostly syscall.open and syscall.open.return
>>>>
>>>> on CentOS release 6.9 (Final)
>>>> kernel 2.6.32-696.3.2.el6.x86_64 #1 SMP Tue Jun 20 01:26:55 UTC 2017
>>>> x86_64 x86_64 x86_64 GNU/Linux
>>>>
>>>> g++ (GCC) 5.3.1 20160406 (Red Hat 5.3.1-6)
>>>>
>>>> I use a custom build of 3.1 release of Systemtap
>>>> Systemtap translator/driver (version 3.1/0.164, commit
>>>> release-2.9-1416-gb8ea350dc13a)
>>>> Copyright (C) 2005-2017 Red Hat, Inc. and others
>>>> This is free software; see the source for copying conditions.
>>>> tested kernel versions: 2.6.18 ... 4.10-rc8
>>>> enabled features: PYTHON2 NLS
>>>>
>>>> Build command stap -g -p4 -m test_open -g --suppress-time-limits -v -k
>>>> -D MAXSKIPPED=0 -D MAXTRYLOCK=100000 -D TRYLOCKDELAY=1 test_open.stp
>>>>
>>>> I restart the script using the following bash one liner
>>>> count=0;while [ 1 ];do echo $count;count=$(($count+1));sudo rmmod
>>>> test_open;sudo staprun test_open.ko -L  ;done;
>>>>
>>>> 30-50 restarts later I get an exception:
>>>>
>>>> Aug 24 10:13:52 localhost kernel: <#DB>  [<ffffffff81068244>] ?
>>>> __schedule_bug+0x44/0x50
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff8154af4c>] ? schedule+0xa4c/0xb70
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff812a6356>] ? vsnprintf+0x336/0x5e0
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff810740aa>] ?
>>>> __cond_resched+0x2a/0x40
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff8154b340>] ? _cond_resched+0x30/0x40
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff812a8cda>] ?
>>>> strncpy_from_user+0x4a/0x90
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffffa0703fb0>] ?
>>>> function___global_user_string_quoted__overload_0+0x460/0x890
>>>> [test_open]
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffffa070281e>] ?
>>>> _new_map_create+0x3e/0xa0 [test_open]
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffffa07047f1>] ?
>>>> probe_3606+0x101/0x400 [test_open]
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81196da1>] ? sys_open+0x1/0x30
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffffa0707ce0>] ?
>>>> enter_kprobe_probe+0x1c0/0x2d0 [test_open]
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff815513fb>] ?
>>>> aggr_pre_handler+0x5b/0xb0
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81196da0>] ? sys_open+0x0/0x30
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81196da1>] ? sys_open+0x1/0x30
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81550e15>] ?
>>>> kprobe_exceptions_notify+0x3d5/0x430
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81551085>] ?
>>>> notifier_call_chain+0x55/0x80
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff815510ea>] ?
>>>> atomic_notifier_call_chain+0x1a/0x20
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff810acd0e>] ? notify_die+0x2e/0x30
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff8154e955>] ? do_int3+0x35/0xb0
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff8154e1c3>] ? int3+0x33/0x40
>>>> Aug 24 10:13:52 localhost kernel: [<ffffffff81196da0>] ? sys_open+0x0/0x30
>>>>
>>>> Thank you, Arkady.