Socket deadlock on ss_send() from thread context

[krizhanovsky]

Sharded cache (cache 1 in configuration file) calls ss_send() from workqueue context and faces deadlock on getting immediate response from upstream server running on the same VM.

    BUG: soft lockup - CPU#1 stuck for 22s! [kworker/u4:3:209]
    Modules linked in: tfw_frang(O) tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables iptable_filter ip_tables ebtable_nat ebtables xfs exportfs ppdev dm_mirror microcode parport_pc dm_region_hash parport pcspkr i2c_piix4 i2c_core serio_raw dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4
    CPU: 1 PID: 209 Comm: kworker/u4:3 Tainted: G           O 3.10.10+ #28
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
    Workqueue: tfw_cache_wq tfw_cache_resp_process_node [tempesta_fw]
    task: ffff880001d18000 ti: ffff880037064000 task.ti: ffff880037064000
    RIP: 0010:[<ffffffff814d30e2>]  [<ffffffff814d30e2>] _raw_spin_lock+0x22/0x30
    RSP: 0018:ffff88007fd03b98  EFLAGS: 00000297
    RAX: 0000000000000003 RBX: ffff88007fd03b20 RCX: 0000000000000004
    RDX: 0000000000000004 RSI: 0000000000000000 RDI: ffff880041c16890
    RBP: ffff88007fd03b98 R08: ffffffff8143c2c0 R09: ffff880001eddd40
    R10: 0000000000000062 R11: ffffffffa03bbf18 R12: ffff88007fd03b08
    R13: ffffffff814dbe0a R14: ffff88007fd03b98 R15: ffffffff81a96d00
    FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    CR2: 00007f9a3035e018 CR3: 000000005b5c1000 CR4: 00000000000006e0
    DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    Stack:
     ffff88007fd03c10 ffffffff81461d2a 0000000000000001 ffff880001eddd40
     ffffffff8143c2c0 ffff88005bce8000 ffff88005bce8000 ffff88007fd03c38
     ffffffff814336a4 ffffffff8143c2c0 ffff880001eddd40 ffffffff816699e0
    Call Trace:
     <IRQ> 
     [<ffffffff81461d2a>] tcp_v4_rcv+0x66a/0x7e0
     [<ffffffff8143c2c0>] ? ip_rcv_finish+0x320/0x320
     [<ffffffff814336a4>] ? nf_hook_slow+0x74/0x130
     [<ffffffff8143c2c0>] ? ip_rcv_finish+0x320/0x320
     [<ffffffff8143c390>] ip_local_deliver_finish+0xd0/0x210
     [<ffffffff8143c6a8>] ip_local_deliver+0x88/0x90
     [<ffffffff8143c018>] ip_rcv_finish+0x78/0x320
     [<ffffffff8143c91d>] ip_rcv+0x26d/0x390
     [<ffffffff81405776>] __netif_receive_skb_core+0x5e6/0x820
     [<ffffffff81461f00>] ? tcp4_gro_receive+0x40/0x130
     [<ffffffff814059cd>] __netif_receive_skb+0x1d/0x60
     [<ffffffff81405a3d>] netif_receive_skb+0x2d/0x90
     [<ffffffff814063e0>] napi_gro_receive+0x80/0xb0
     [<ffffffffa009c4c3>] e1000_clean_rx_irq+0x2b3/0x580 [e1000]
     [<ffffffffa009e9d5>] e1000_clean+0x255/0x8c0 [e1000]
     [<ffffffff810708ef>] ? scheduler_tick+0xff/0x140
     [<ffffffff81405d79>] net_rx_action+0x139/0x220
     [<ffffffff810461f0>] __do_softirq+0x100/0x250
     [<ffffffff814dc47c>] call_softirq+0x1c/0x30
     <EOI> 
     [<ffffffff810041ed>] do_softirq+0x3d/0x80
     [<ffffffff81045814>] local_bh_enable+0x94/0xa0
     [<ffffffff81440828>] ip_finish_output+0x1b8/0x3b0
     [<ffffffff81441d70>] ip_output+0x90/0xa0
     [<ffffffff81441495>] ip_local_out+0x25/0x30
     [<ffffffff814417eb>] ip_queue_xmit+0x14b/0x3f0
     [<ffffffff81458f2d>] tcp_transmit_skb+0x45d/0x8c0
     [<ffffffff81459524>] tcp_write_xmit+0x194/0xb90
     [<ffffffff8145a13e>] __tcp_push_pending_frames+0x2e/0xc0
     [<ffffffff81449030>] tcp_push+0x70/0x90
     [<ffffffffa0474b88>] ss_send+0x35b/0x374 [tempesta_fw]
     [<ffffffffa044f2b8>] tfw_connection_send+0x39/0x3b [tempesta_fw]
     [<ffffffffa04528f7>] tfw_http_resp_cache_cb+0x60/0x7a [tempesta_fw]
     [<ffffffffa04495e9>] tfw_cache_resp_process_node+0x39/0x51 [tempesta_fw]
     [<ffffffff8105b409>] process_one_work+0x179/0x440
     [<ffffffff8105c04b>] worker_thread+0x11b/0x390
     [<ffffffff8105bf30>] ? manage_workers.isra.25+0x2a0/0x2a0
     [<ffffffff810620c0>] kthread+0xc0/0xd0
     [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
     [<ffffffff814db19c>] ret_from_fork+0x7c/0xb0
     [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
    Code: 66 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 e5 b8 00 00 01 00 f0 0f c1 07 89 c1 c1 e9 10 66 39 c1 89 ca 74 0c 66 90 f3 90 <0f> b7 07 66 39 d0 75 f6 5d c3 0f 1f 40 00 0f 1f 44 00 00 55 48 

[krizhanovsky]

Related to #343: affects work queues for sharded cache as well as tfw_bomber.

[krizhanovsky]

There are several problems leading to the deadlock:

• Linux kernel uses sk_lock as a mutex for user space synchronization and spin lock for softirq synchronization, so it's supposed that thread context should use the mutex and we need specialized versions of at least ss_send() and ss_close() to be used in thread context;
• the previous point leads us to necessity to correctly socket backlog queue;
• ss_tcp_process_data() can be called w/o acquired socket lock through release_sock() -> tcp_v4_do_rcv() chain and we get the deadlock after ulocking unlocked spin lock.

However, it seems this list is incomplete since I still have deadlock after fixing the problems.

[krizhanovsky]

There is one more concurrency issue: TSQ calls tcp_write_xmit() in tasklet context competing with softirq.

tcp_write_xmit() used in ss_send() doesn't send data if sk->sk_wmem_alloc is higher than dynamically determined limit based on TSQ's sysctl_tcp_limit_output_bytes. The data is sent only when ss_send() is called next time or due to tasklet activation.

[krizhanovsky]

The issue is fixed in sense of #391. Verified by running bomber against Apache HTTPD:

    # ./tfw_bomber.sh -a 127.0.0.1:8080 -c 20 -i 10 -m 30 -t 2 --start
    Tempesta: bombing the server...
    done