srs-bench pressure test REUSE PORT multiple processes report "publish timeout, (Interrupted system call)" error

[limjoe]

Description'

Please ensure that you maintain the markdown structure.

srs-bench performs concurrent stress testing on the local machine with 1500 streams. The video information is 1007kbps.1920x1080.flv. When 2 processes are started at port 1935, occasional errors of push stream timeout occur.

The single-core CPUs are not fully utilized, running at around 50% to 70%.

Environment

1. SRS Version: 3.0 alpha5(3.0.75)

1. Operating System: Ubuntu 16.04
2. Server Type: This issue occurs on both local server and Kingsoft Cloud server.
3. SRS Log:

[2019-12-24 20:02:00.405][Trace][3107][2615] cleanup when unpublish
[2019-12-24 20:02:00.406][Error][3107][2615][4] serve error code=1011 : service cycle : rtmp: stream service : rtmp: publish timeout 5000ms, nb_msgs=1332
thread [2615]: do_cycle() [src/app/srs_app_rtmp_conn.cpp:210][errno=4]
thread [2615]: service_cycle() [src/app/srs_app_rtmp_conn.cpp:400][errno=4]
thread [2615]: do_publishing() [src/app/srs_app_rtmp_conn.cpp:896][errno=62](Interrupted system call)
[2019-12-24 20:02:00.406][Trace][3107][2583] cleanup when unpublish
[2019-12-24 20:02:00.406][Error][3107][2583][4] serve error code=1011 : service cycle : rtmp: stream service : rtmp: publish timeout 5000ms, nb_msgs=1332
thread [2583]: do_cycle() [src/app/srs_app_rtmp_conn.cpp:210][errno=4]
thread [2583]: service_cycle() [src/app/srs_app_rtmp_conn.cpp:400][errno=4]
thread [2583]: do_publishing() [src/app/srs_app_rtmp_conn.cpp:896][errno=62](Interrupted system call)
[2019-12-24 20:02:00.406][Trace][3107][1995] cleanup when unpublish
[2019-12-24 20:02:00.406][Error][3107][1995][4] serve error code=1011 : service cycle : rtmp: stream service : rtmp: publish timeout 5000ms, nb_msgs=6404
thread [1995]: do_cycle() [src/app/srs_app_rtmp_conn.cpp:210][errno=4]
thread [1995]: service_cycle() [src/app/srs_app_rtmp_conn.cpp:400][errno=4]
thread [1995]: do_publishing() [src/app/srs_app_rtmp_conn.cpp:896][errno=62](Interrupted system call)

Reproduction (Replay)

Steps to reproduce the bug:

1. Use srs-benc to concurrently push 1500 streams.
2. Set the video bitrate to around 1000KB.

1. Configuration of origin_server_1:

listen              1935;
max_connections     1000;
daemon              off;
srs_log_tank        console;
pid                 ./objs/origin.cluster.serverA.pid;

http_api {
    enabled         on;
    listen          1985;
    crossdomain     on;
}

vhost __defaultVhost__ {
   min_latency     on;
    tcp_nodelay     on;

    publish {
        mr off;
    }

    play {
        gop_cache       off;
        queue_length    10;
        mw_latency      100;
    }

    hls {
        enabled         on;
        hls_fragment    6;
        hls_window      15;
        hls_path        ./objs/nginx/html;
        hls_m3u8_file   [app]/[stream].m3u8;
        hls_ts_file     [app]/[stream]/[timestamp].ts;
        hls_cleanup     on;
        hls_nb_notify   64;
        hls_wait_keyframe       on;

    }
}

1. Configuration of origin_server_2:

listen              1935;
max_connections     1000;
daemon              off;
srs_log_tank        console;
pid                 ./objs/origin.cluster.serverB.pid;

http_api {
    enabled         on;
    listen          1986;
    crossdomain     on;
}

vhost __defaultVhost__ {
   min_latency     on;
    tcp_nodelay     on;

    publish {
        mr off;
    }

    play {
        gop_cache       off;
        queue_length    10;
        mw_latency      100;
    }

    hls {
        enabled         on;
        hls_fragment    6;
        hls_window      15;
        hls_path        ./objs/nginx/html;
        hls_m3u8_file   [app]/[stream].m3u8;
        hls_ts_file     [app]/[stream]/[timestamp].ts;
        hls_cleanup     on;
        hls_nb_notify   64;
        hls_wait_keyframe       on;

    }
}

Expected Behavior (Expect)

Describe what you expect to happen.
Normal streaming, able to complete CPU processing.

Other Information

In addition, version 2.0 also has this issue on local machines.

TRANS_BY_GPT3

[limjoe]

ulimit set to 10240 but still occasionally occurs

TRANS_BY_GPT3

[limjoe]

gprof analysis results are visualized. Link: https://pan.baidu.com/s/17FlO0-A8k4zQudy-uK8IYg Extraction code: jm4k

TRANS_BY_GPT3

[limjoe]

The reason has been found: when writing HLS slices to the disk, there is high disk IO, which causes scheduling delays.

For later deployment, it is necessary to avoid this issue.

TRANS_BY_GPT3

[alphonsetai]

I have encountered this problem while doing SRS-Brench stress testing. It is best to check the IO situation. If the file IOPS is too high, you can try turning off the HLS configuration.

@winlinvip
I previously mentioned a discussion about an HTTP hook. However, after reviewing the code, I found that the TCP connect request and file IO request are both synchronous functions. This cannot be scheduled as a user-level micro-thread in a coroutine, which leads to task pauses. Under the current IO operations, the only way to improve this is by stacking IO performance, but ultimately, it cannot change the current situation.

This might require considering optimization directions.

TRANS_BY_GPT3

[limjoe]

@alphonsetai Hmm, I have verified it, disabling hls will not cause a timeout.

TRANS_BY_GPT3

[winlinvip]

I roughly looked at it. When running Docker on a Mac with 2000 streaming pulls, there was one timeout.

8213:[2019-12-25 02:32:55.835][Trace][2371][2907] RTMP client ip=127.0.0.1, fd=1995
9244:[2019-12-25 02:32:55.982][Trace][2371][2907] simple handshake success.
9245:[2019-12-25 02:32:55.982][Trace][2371][2907] connect app, tcUrl=rtmp://127.0.0.1/live, pageUrl=, swfUrl=, schema=rtmp, vhost=127.0.0.1, port=1935, app=live, args=null
9246:[2019-12-25 02:32:55.982][Trace][2371][2907] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
10861:[2019-12-25 02:32:56.290][Trace][2371][2907] client identified, type=Play, vhost=127.0.0.1, app=live, stream=livestream, param=, duration=-1ms
10862:[2019-12-25 02:32:56.290][Trace][2371][2907] connected stream, tcUrl=rtmp://127.0.0.1/live, pageUrl=, swfUrl=, schema=rtmp, vhost=__defaultVhost__, port=1935, app=live, stream=livestream, param=, args=null
10863:[2019-12-25 02:32:56.290][Trace][2371][2907] source url=/live/livestream, ip=127.0.0.1, cache=1, is_edge=0, source_id=922[922]
10864:[2019-12-25 02:32:56.290][Trace][2371][2907] dispatch cached gop success. count=91, duration=1330
10865:[2019-12-25 02:32:56.290][Trace][2371][2907] create consumer, queue_size=0.00, jitter=30000000
10866:[2019-12-25 02:32:56.290][Trace][2371][2907] set fd=1995, SO_SNDBUF=2626560=>175000, buffer=350ms
10867:[2019-12-25 02:32:56.291][Trace][2371][2907] start play smi=0ms, mw_sleep=350, mw_enabled=1, realtime=0, tcp_nodelay=0
12862:[2019-12-25 02:35:51.308][Trace][2371][2907] update source_id=2923[2923]
13260:[2019-12-25 02:35:59.002][Warn][2371][2907][11] resize iovs 2048 => 4096, max_msgs=128
15346:[2019-12-25 02:39:27.821][Trace][2371][2907] update source_id=2924[2924]
17160:[2019-12-25 02:40:07.394][Error][2371][2907][4] serve error code=1011 : service cycle : rtmp: stream service : rtmp: send 24 messages : send messages : writev : writev timeout 30000 ms
17161:thread [2907]: do_cycle() [src/app/srs_app_rtmp_conn.cpp:210][errno=4]
17162:thread [2907]: service_cycle() [src/app/srs_app_rtmp_conn.cpp:400][errno=4]
17163:thread [2907]: do_playing() [src/app/srs_app_rtmp_conn.cpp:784][errno=62]
17164:thread [2907]: send_and_free_messages() [src/protocol/srs_rtmp_stack.cpp:834][errno=62]
17165:thread [2907]: srs_write_large_iovs() [src/protocol/srs_protocol_utility.cpp:341][errno=62]
17166:thread [2907]: writev() [src/service/srs_service_st.cpp:565][errno=62](Interrupted system call)

In the 3 seconds before the error occurred, there were instances of FFMEPG restarting the ingest, specifically after the avatar sample ended. Generally, in the first few seconds, there will be a large number of I-frames, resulting in a significant amount of data. Due to the large number of clients, it is equivalent to suddenly needing to send a large amount of data to 2000 clients, causing an increase in iovs.

13260:[2019-12-25 02:35:59.002][Warn][2371][2907][11] resize iovs 2048 => 4096, max_msgs=128

The streaming logs also show an increase in the queue size.

[2019-12-25 02:39:52.462][Warn][2371][2924][11] fast vector incrase 1024=>2048

This is because by default, SRS accumulates several hundred milliseconds of data before sending it to the client in one writev operation, which greatly reduces syscalls and improves performance. If the amount of data to be sent is very large, this may cause data accumulation for certain clients, which needs to be confirmed.

TRANS_BY_GPT3

[winlinvip]

I have encountered this problem before when conducting srs-brench stress testing. It is best to check the IO situation. If the file IOPS is too high, you can try turning off the HLS configuration and see.

@winlinvip
I previously mentioned a discussion about an HTTP hook. After examining the code, I found that the TCP connect request and file IO request are both synchronous functions. This cannot be scheduled as a user-level micro-thread in a coroutine, which leads to task pauses. Under the current IO operations, the only way to improve this issue is to stack IO performance, but ultimately, the situation cannot be changed.

This may require considering optimization directions.

There is no problem with the TCP connection establishment. The disk IO is not using st_write but directly using write, which can cause this issue. This area is indeed worth optimizing.

TRANS_BY_GPT3

[limjoe]

@winlinvip Are you considering optimizing this before the official release of version 3.0?

TRANS_BY_GPT3

[winlinvip]

SRS 3 will not have major modifications, only bug fixes. This change is also not insignificant and will not be included in SRS3.

Currently, it is recommended to work around this issue by using a memory disk.

TRANS_BY_GPT3

[winlinvip]

Created a new feature tracking, refer to #1540'
Please make sure to maintain the markdown structure.

TRANS_BY_GPT3