[LTP] [PATCH] pty04: Avoid receiving packets from all interfaces
Richard Palethorpe
rpalethorpe@suse.de
Fri May 15 15:27:00 CEST 2020
Hello,
Jan Stancek <jstancek@redhat.com> writes:
> ----- Original Message -----
>>
>>
>> ----- Original Message -----
>> > Hi!
>> > Sounds reasonable, also hope it's the last patch. :-)
>> >
>> > @Jan do you want to test this as well, or should I apply and proceed
>> > with the release?
>>
>> I haven't spotted potential issue while looking at kernel code,
>> will test the patch just to be sure.
>
> It still gets occasionally stuck on 5.7.0-rc4, but the chance to hit
> it appears lower. I think merge the patch and we'll see how frequently
> it happens with single iteration. We can always disable it later in
> runtest file.
>
> # ./pty04 -i 10
> tst_test.c:1246: INFO: Timeout per run is 0h 05m 00s
> pty04.c:130: INFO: PTS path is /dev/pts/2
> pty04.c:207: INFO: Netdev is sl0
> pty04.c:216: INFO: Netdev MTU is 8192 (we set 8192)
> pty04.c:233: INFO: Bound netdev 245 to socket 5
> tst_buffers.c:55: INFO: Test is using guarded buffers
> pty04.c:324: INFO: Reading from socket 5
> tst_buffers.c:55: INFO: Test is using guarded buffers
> pty04.c:180: PASS: Wrote PTY N_SLIP 3 (1)
> pty04.c:191: PASS: Wrote PTY N_SLIP 3 (2)
> pty04.c:328: PASS: Read netdev N_SLIP 5 (1)
>
>
> tst_checkpoint.c:149: BROK: pty04.c:364: tst_checkpoint_wait(0, 100000): ETIMEDOUT (110)
> tst_test.c:373: BROK: Reported by child (2990)
> pty04.c:306: BROK: Read 0 of 8191 bytes: ENETDOWN (100)
> pty04.c:196: PASS: Writing to PTY interrupted by hangup
> tst_test.c:373: WARN: Reported by child (2987)
Thanks for testing. I guess if the timeout is set long enough and you
have RCU stall detection enabled(?) or SLUB debug, then you will get
some stack trace. Probably related to memory allocation.
I tried again running it in parallel and still got the following stack
traces, but the system is able to recover afterwards. It seems like the
PTYs and line disciplines are a bit fragile. Which I suspect could be
fixed by using different memory pools , but I'm not sure it is very
important.
[ 58.454313] rcu: INFO: rcu_sched self-detected stall on CPU
[ 58.455115] rcu: 2-....: (26000 ticks this GP) idle=bea/1/0x4000000000000002 softirq=2439/2439 fqs
[ 58.456405] (t=26003 jiffies g=4233 q=26)
[ 58.456949] NMI backtrace for cpu 2
[ 58.457405] CPU: 2 PID: 280 Comm: kworker/u8:6 Not tainted 5.7.0-rc4+ #49
[ 58.458286] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt4
[ 58.459766] Workqueue: events_unbound flush_to_ldisc
[ 58.460438] Call Trace:
[ 58.460777] <IRQ>
[ 58.461063] dump_stack+0x97/0xe0
[ 58.461518] nmi_cpu_backtrace.cold+0x46/0x80
[ 58.462103] ? lapic_can_unplug_cpu.cold+0x46/0x46
[ 58.462741] nmi_trigger_cpumask_backtrace+0x125/0x154
[ 58.463438] rcu_dump_cpu_stacks+0x1a0/0x1ea
[ 58.464041] rcu_sched_clock_irq.cold+0x518/0x978
[ 58.464683] update_process_times+0x24/0x50
[ 58.465248] tick_sched_handle+0xf7/0x160
[ 58.465792] tick_sched_timer+0x38/0xf0
[ 58.466315] __hrtimer_run_queues+0x4ae/0xa90
[ 58.466902] ? tick_sched_do_timer+0x150/0x150
[ 58.467523] ? enqueue_hrtimer+0x2d0/0x2d0
[ 58.468092] hrtimer_interrupt+0x2bf/0x740
[ 58.468668] smp_apic_timer_interrupt+0x109/0x4e0
[ 58.469303] apic_timer_interrupt+0xf/0x20
[ 58.469852] </IRQ>
[ 58.470150] RIP: 0010:enqueue_to_backlog+0x156/0xb40
[ 58.470821] Code: 74 08 3c 03 0f 8e 90 05 00 00 83 83 30 01 00 00 01 4c 89 ef e8 5b f4 7a 00 41 f7 c4 f
[ 58.473235] RSP: 0018:ffffc900005479b0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
[ 58.474225] RAX: 0000000000000007 RBX: ffff88806b535d80 RCX: 1ffffffff1e2bffa
[ 58.475155] RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffffffff8d42ee73
[ 58.476090] RBP: ffff888048188c80 R08: 0000000000000001 R09: ffffed100d6a6bdb
[ 58.477068] R10: ffff88806b535ed3 R11: ffffed100d6a6bda R12: 0000000000000282
[ 58.478003] R13: ffff88806b535ed0 R14: ffff888048188c90 R15: 00000000000003e9
[ 58.479059] ? enqueue_to_backlog+0x153/0xb40
[ 58.479674] netif_rx_internal+0xc6/0x450
[ 58.480265] ? enqueue_to_backlog+0xb40/0xb40
[ 58.480985] netif_rx_ni+0x4b/0x3a0
[ 58.481545] slcan_receive_buf+0x970/0xbb0 [slcan]
[ 58.482295] ? slcan_transmit+0x3e0/0x3e0 [slcan]
[ 58.483047] ? slcan_transmit+0x3e0/0x3e0 [slcan]
[ 58.483793] ? slcan_transmit+0x3e0/0x3e0 [slcan]
[ 58.484544] tty_ldisc_receive_buf+0x100/0x1d0
[ 58.485246] ? tty_ldisc_receive_buf+0x5/0x1d0
[ 58.485970] tty_port_default_receive_buf+0x61/0x90
[ 58.486576] flush_to_ldisc+0x1a7/0x3e0
[ 58.487046] process_one_work+0x926/0x16d0
[ 58.487550] ? pwq_dec_nr_in_flight+0x290/0x290
[ 58.488077] ? ftrace_graph_caller+0x6b/0xa0
[ 58.488584] ? rwlock_bug.part.0+0x90/0x90
[ 58.489081] worker_thread+0x92/0xfa0
[ 58.489535] ? process_one_work+0x16d0/0x16d0
[ 58.490048] kthread+0x2ba/0x3b0
[ 58.490433] ? kthread_create_on_node+0xd0/0xd0
[ 58.490966] ret_from_fork+0x3a/0x50
[ 59.114357] rcu: INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 2-... } 26468 jiffies s: 2.
[ 59.115656] rcu: blocking rcu_node structures:
[ 59.116176] Task dump for CPU 2:
[ 59.116580] kworker/u8:6 R running task 28768 280 2 0x80004008
[ 59.117488] Workqueue: events_unbound flush_to_ldisc
[ 59.118068] Call Trace:
[ 59.118409] ? pwq_dec_nr_in_flight+0x290/0x290
[ 59.118936] ? ftrace_graph_caller+0x6b/0xa0
[ 59.119476] ? rwlock_bug.part.0+0x90/0x90
[ 59.119976] ? worker_thread+0x92/0xfa0
[ 59.120472] ? process_one_work+0x16d0/0x16d0
[ 59.120987] ? kthread+0x2ba/0x3b0
[ 59.121415] ? kthread_create_on_node+0xd0/0xd0
[ 59.121948] ? ret_from_fork+0x3a/0x50
[ 63.805607] warn_alloc: 1915 callbacks suppressed
[ 26.819715] reproducer: page allocation failure: order:1, mode:0x40a20(GFP_ATOMIC|__GFP_COMP), nodemas0
[ 26.820140] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.821191] CPU: 1 PID: 456 Comm: reproducer Not tainted 5.7.0-rc4+ #49
[ 26.822013] cache: skbuff_head_cache, object size: 224, buffer size: 320, default order: 1, min orde0
[ 26.822583] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822590] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822596] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822604] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822712] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822719] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822724] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822732] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822760] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822767] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822772] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822780] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822807] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.0-59-gc9ba527-rebuilt4
[ 26.822813] Call Trace:
[ 26.822818] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822823] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822828] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822834] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822870] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822876] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822882] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822890] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822932] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.822939] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.822946] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.822953] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.822995] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.823002] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.823007] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.823015] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.823057] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.823064] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.823069] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.823076] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.823116] SLUB: Unable to allocate memory on node -1, gfp=0xa20(GFP_ATOMIC)
[ 26.823121] cache: kmalloc-4k, object size: 4096, buffer size: 8192, default order: 3, min order: 1
[ 26.823128] kmalloc-4k debugging increased min order, use slub_debug=O to disable.
[ 26.823134] node 0: slabs: 44294, objs: 177164, free: 0
[ 26.824222] node 0: slabs: 12353, objs: 308825, free: 0
[ 26.825031] dump_stack+0x97/0xe0
[ 26.859539] warn_alloc.cold+0x87/0x18d
pty04.c:328: 26.860015] ? zone_watermark_ok_safe+0x270/0x270
;32mPASS: Re[ 26.860709] ? zone_watermark_ok_safe+0x270/0x270
ad netdev N_SLCA[ 26.861611] ? __alloc_pages_slowpath.constprop.0+0x1cf3/0x2180
N 26 (1)[ 26.862395] ? prepare_ftrace_return+0xa1/0xf0
[ 26.863008] ? wakeup_kcompactd+0x18a/0x3e0
[ 26.863526] ? __isolate_free_page+0x4e0/0x4e0
[ 26.864070] __alloc_pages_slowpath.constprop.0+0x1cf3/0x2180
[ 26.864739] ? get_page_from_freelist+0x753/0x3920
pty04.c:332: 26.865300] ? __isolate_free_page+0x4e0/0x4e0
;32mPASS: Re[ 26.865989] ? __alloc_pages_nodemask+0x277/0x6e0
ad netdev N_SLCA[ 26.866675] ? warn_alloc+0x120/0x120
N 26 (2)
[ 26.867260] ? ftrace_graph_caller+0x6b/0xa0
[ 26.867867] ? function_graph_enter+0x34b/0x520
[ 26.868396] ? __isolate_free_page+0x4e0/0x4e0
[ 26.868914] ? ftrace_graph_stop+0x10/0x10
[ 26.869409] __alloc_pages_nodemask+0x517/0x6e0
[ 26.869942] ? __alloc_pages_slowpath.constprop.0+0x2180/0x2180
[ 26.870618] ? ftrace_graph_caller+0x6b/0xa0
[ 26.871141] new_slab+0x28b/0x340
[ 26.871547] ___slab_alloc+0x370/0x5d0
[ 26.871995] ? __tty_buffer_request_room+0x1c0/0x560
[ 26.872577] ? __tty_buffer_request_room+0x1c0/0x560
[ 26.873150] ? ftrace_graph_caller+0x6b/0xa0
[ 26.873645] ? prepare_ftrace_return+0xa1/0xf0
[ 26.874172] ? __tty_buffer_request_room+0x1c0/0x560
[ 26.874747] ? __slab_alloc+0x38/0x70
[ 26.875176] __slab_alloc+0x38/0x70
[ 26.875648] ? __tty_buffer_request_room+0x1c0/0x560
[ 26.876403] __kmalloc+0x25e/0x2c0
[ 26.876814] __tty_buffer_request_room+0x1c0/0x560
[ 26.877380] tty_insert_flip_string_fixed_flag+0x7d/0x1f0
[ 26.878181] pty_write+0x103/0x1d0
[ 26.878684] n_tty_write+0x753/0xf90
[ 26.879108] ? ftrace_graph_stop+0x10/0x10
[ 26.879585] ? n_tty_read+0x16e0/0x16e0
[ 26.880053] ? tty_write+0x3c0/0x700
[ 26.880472] ? prepare_ftrace_return+0xa1/0xf0
[ 26.880989] ? n_tty_read+0x16e0/0x16e0
[ 26.881435] ? ftrace_graph_caller+0x6b/0xa0
[ 26.881934] ? prepare_to_wait_exclusive+0x200/0x200
[ 26.882509] ? n_tty_read+0x16e0/0x16e0
[ 26.882973] tty_write+0x3c0/0x700
[ 26.883379] ? n_tty_read+0x16e0/0x16e0
[ 26.883857] vfs_write+0x154/0x450
[ 26.884324] ksys_write+0xf9/0x1d0
[ 26.884783] ? __ia32_sys_read+0xb0/0xb0
[ 26.885324] do_syscall_64+0x95/0x4a0
[ 26.885819] entry_SYSCALL_64_after_hwframe+0x49/0xb3
[ 26.886485] RIP: 0033:0x7f56ae533563
[ 26.886961] Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb bb 0f 1f 80 00 00 00 00 64 8b 04 25 18 8
[ 26.889355] RSP: 002b:00007ffc3026c138 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 26.890335] RAX: ffffffffffffffda RBX: 0000000000422600 RCX: 00007f56ae533563
[ 26.891258] RDX: 0000000000002000 RSI: 00007f56ae42a000 RDI: 0000000000000015
[ 26.892206] RBP: 00007f56ae60a580 R08: 0000000000000000 R09: 00007ffc3026ba80
[ 26.893231] R10: 00000000000003cb R11: 0000000000000246 R12: 0000000000002000
[ 26.894077] R13: 00007f56ae42a000 R14: 0000000000000015 R15: 0000000000000001
[ 26.895141] Mem-Info:
[ 26.895441] active_anon:3997 inactive_anon:4284 isolated_anon:0
[ 26.895441] active_file:0 inactive_file:0 isolated_file:0
[ 26.895441] unevictable:0 dirty:0 writeback:0 unstable:0
[ 26.895441] slab_reclaimable:4267 slab_unreclaimable:385849
[ 26.895441] mapped:913 shmem:7230 pagetables:205 bounce:0
[ 26.895441] free:5770 free_pcp:737 free_cma:0
[ 26.899022] Node 0 active_anon:15988kB inactive_anon:17136kB active_file:0kB inactive_file:0kB unevicts
[ 26.902008] Node 0 DMA free:6340kB min:444kB low:552kB high:660kB reserved_highatomic:2048KB active_anB
[ 26.905162] lowmem_reserve[]: 0 1548 1548 1548 1548
[ 26.905737] Node 0 DMA32 free:16612kB min:44608kB low:55760kB high:66912kB reserved_highatomic:18432KBB
[ 26.909330] lowmem_reserve[]: 0 0 0 0 0
[ 26.909856] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 0*32kB 1*64kB (H) 1*128kB (H) 0*256kB 0*512kB 0*1024kB B
[ 26.911422] Node 0 DMA32: 45*4kB (ME) 18*8kB (UME) 4*16kB (UME) 11*32kB (UM) 3*64kB (M) 2*128kB (UM) 1B
[ 26.913285] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[ 26.914279] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[ 26.915231] 7230 total pagecache pages
[ 26.915672] 0 pages in swap cache
[ 26.916068] Swap cache stats: add 0, delete 0, find 0/0
[ 26.916666] Free swap = 0kB
[ 26.917006] Total swap = 0kB
[ 26.917345] 524156 pages RAM
[ 26.917686] 0 pages HighMem/MovableOnly
[ 26.918130] 115119 pages reserved
--
Thank you,
Richard.
More information about the ltp
mailing list