session-replay-tools / tcpcopy

An online request replication and TCP stream replay tool, ideal for real testing, performance testing, stability testing, stress testing, load testing, smoke testing, and more.
http://session-replay-tools.github.io/tcpcopy/
Other
4.48k stars 1.03k forks source link

slide win:too many packs 问题 #378

Closed yumao123 closed 2 months ago

yumao123 commented 4 years ago

hi,王工你好 我们在使用tcpcopy+intercept做压测过程中发现,当使用离线模式(offline),在高压情况下(QPS过万),tcpcopy无法正常回放数据 查看tcpcopy有大量日志提示:slide win:too many packs:1409,p:43751,如下

2020/07/27 18:06:51 +577 [notice] tcpcopy version:1.2.0 2020/07/27 18:06:51 +577 [notice] tcpcopy internal version:6 2020/07/27 18:06:51 +577 [notice] target:19611-10.1.115.54:19621 2020/07/27 18:06:51 +577 [notice] TC_OFFLINE mode 2020/07/27 18:06:51 +577 [notice] TC_COMBINED mode 2020/07/27 18:06:51 +577 [notice] epoll mode 2020/07/27 18:06:51 +577 [notice] TC_DETECT_MEMORY is true 2020/07/27 18:06:51 +577 [notice] session timeout:120 2020/07/27 18:06:51 +577 [notice] keepalive timeout:240 2020/07/27 18:06:51 +577 [notice] min sess pool size:624 2020/07/27 18:06:51 +577 [notice] sess pool size:1024 2020/07/27 18:06:51 +577 [notice] set global port for tcpcopy 2020/07/27 18:06:51 +577 [notice] raw_clt_tf_ip:10.1.100.x 2020/07/27 18:06:51 +577 [notice] parallel connections per target:2 2020/07/27 18:06:51 +577 [notice] accelerated 1 times,interval:0 ms 2020/07/27 18:06:51 +577 [notice] s parameter:10.1.115.32 2020/07/27 18:06:51 +577 [notice] set only ip for tcpcopy 2020/07/27 18:06:51 +577 [debug] pool:0x1c5c370, add timer:0x1c5c420 2020/07/27 18:06:51 +577 [debug] pool:0x1c5c370, add timer:0x1c5c470 2020/07/27 18:06:51 +577 [info] connect to remote server(10.1.115.32:36524) 2020/07/27 18:06:51 +577 [info] connect to remote server(10.1.115.32:36524) 2020/07/27 18:06:51 +577 [notice] open pcap success:online.pcap 2020/07/27 18:06:51 +577 [notice] send the first packets here 2020/07/27 18:06:51 +577 [info] pl:29841536, p:43703 2020/07/27 18:06:51 +577 [debug] pool:0x1c75880, add timer:0x1c759f8 2020/07/27 18:06:51 +577 [info] nev:29841888,p:43703 2020/07/27 18:06:51 +577 [debug] pool:0x1c75880, add timer:0x1c75a48 2020/07/27 18:06:51 +577 [notice] session key:1529025836970, p:43703 2020/07/27 18:06:51 +577 [debug] recv clt:10.1.100.1:43703-->10.1.115.14:19611,len 146,seq=3465558477,ack=79002035 2020/07/27 18:06:51 +577 [info] ln:29842296, pkt:29842128, save:3465558477,p:43703 2020/07/27 18:06:51 +577 [info] slide_win_packs size:1, p:43703 2020/07/27 18:06:51 +577 [debug] proc clt pack:43703 2020/07/27 18:06:51 +577 [debug] fake syn:43703 2020/07/27 18:06:51 +577 [debug] to bak:10.1.100.1:43703-->10.1.115.54:19621,len 44,seq=3465558476,ack=0 2020/07/27 18:06:51 +577 [info] rtt:1,p:43703 2020/07/27 18:06:51 +577 [info] pl:29842576, p:43693 2020/07/27 18:06:51 +577 [debug] pool:0x1c75c90, add timer:0x1c75e08 2020/07/27 18:06:51 +577 [info] nev:29842928,p:43693 2020/07/27 18:06:51 +577 [debug] pool:0x1c75c90, add timer:0x1c75e58 2020/07/27 18:06:51 +577 [notice] session key:1529025834410, p:43693 2020/07/27 18:06:51 +577 [debug] recv clt:10.1.100.1:43693-->10.1.115.14:19611,len 146,seq=1501199559,ack=342303419 2020/07/27 18:06:51 +577 [info] ln:29843336, pkt:29843168, save:1501199559,p:43693 2020/07/27 18:06:51 +577 [info] slide_win_packs size:1, p:43693 2020/07/27 18:06:51 +577 [debug] proc clt pack:43693 2020/07/27 18:06:51 +577 [debug] fake syn:43693 2020/07/27 18:06:51 +577 [debug] to bak:10.1.100.1:43693-->10.1.115.54:19621,len 44,seq=1501199558,ack=0 2020/07/27 18:06:51 +577 [info] rtt:1,p:43693 2020/07/27 18:06:51 +577 [debug] pool:0x1c5c370, add timer:0x1c5c530 2020/07/27 18:06:51 +583 [debug] resp packets:1 2020/07/27 18:06:51 +583 [debug] from bak:10.1.115.54:19621-->10.1.100.1:43703,len 44,seq=1065654866,ack=3465558477 2020/07/27 18:06:51 +583 [debug] recv syn from back, size tcp:24, p:43703 2020/07/27 18:06:51 +583 [debug] to bak:10.1.100.1:43703-->10.1.115.54:19621,len 40,seq=3465558477,ack=1065654867 2020/07/27 18:06:51 +583 [info] slide_win_packs size:1, p:43703 2020/07/27 18:06:51 +583 [debug] proc clt pack:43703 2020/07/27 18:06:51 +583 [info] state:2, con len:94,p:43703 2020/07/27 18:06:51 +583 [info] new req from clt:43703 2020/07/27 18:06:51 +583 [debug] pool:0x1c75880, del timer:0x1c759e0 2020/07/27 18:06:51 +583 [debug] pool:0x1c75880, up timer:0x1c759e0 2020/07/27 18:06:51 +583 [debug] to bak:10.1.100.1:43703-->10.1.115.54:19621,len 146,seq=3465558477,ack=1065654867 2020/07/27 18:06:51 +583 [info] empty slide,p:43703 ... 2020/07/27 18:06:54 +591 [warn] slide win:too many packs:1294,p:43703 2020/07/27 18:06:54 +591 [debug] sess post disp:43703 2020/07/27 18:06:54 +591 [debug] send passive rst:43703 2020/07/27 18:06:54 +591 [debug] to bak:10.1.100.1:43703-->10.1.115.54:19621,len 40,seq=3465558571,ack=1065655065 2020/07/27 18:06:54 +591 [info] cont unsend:43703,ack:3465558571,max:3465682933 2020/07/27 18:06:54 +591 [debug] pool:0x1c75880, up timer:0x1c75a30 2020/07/27 18:06:54 +591 [debug] del timer:0x1c75e40 2020/07/27 18:06:54 +591 [info] sess key:1529025834410, check timeout:43693 2020/07/27 18:06:54 +591 [warn] slide win:too many packs:1337,p:43693 2020/07/27 18:06:54 +591 [debug] sess post disp:43693 2020/07/27 18:06:54 +591 [debug] send passive rst:43693 2020/07/27 18:06:54 +591 [debug] to bak:10.1.100.1:43693-->10.1.115.54:19621,len 40,seq=1501199653,ack=3734872465 2020/07/27 18:06:54 +591 [info] cont unsend:43693,ack:1501199653,max:1501328715 2020/07/27 18:06:54 +591 [debug] pool:0x1c75c90, up timer:0x1c75e40 2020/07/27 18:06:54 +591 [debug] del timer:0x1c5c518 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43765-->10.1.115.14:19611,len 146,seq=2835447422,ack=3243449324 2020/07/27 18:06:54 +591 [info] ln:45059264, pkt:45059096, save:2835447422,p:43765 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1401, p:43765 2020/07/27 18:06:54 +591 [debug] proc clt pack:43765 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43765 2020/07/27 18:06:54 +591 [debug] lost pack, seq:2835312438, expect:2835312344,p:43765 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43729-->10.1.115.14:19611,len 146,seq=4029631185,ack=244963957 2020/07/27 18:06:54 +591 [info] ln:45056144, pkt:45055976, save:4029631185,p:43729 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1349, p:43729 2020/07/27 18:06:54 +591 [debug] proc clt pack:43729 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43729 2020/07/27 18:06:54 +591 [debug] lost pack, seq:4029501183, expect:4029500807,p:43729 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43747-->10.1.115.14:19611,len 146,seq=2630193916,ack=2396021842 2020/07/27 18:06:54 +591 [info] ln:45031520, pkt:45031352, save:2630193916,p:43747 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1339, p:43747 2020/07/27 18:06:54 +591 [debug] proc clt pack:43747 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43747 2020/07/27 18:06:54 +591 [debug] lost pack, seq:2630066546, expect:2630066358,p:43747 2020/07/27 18:06:54 +591 [info] del prev sess:43703 2020/07/27 18:06:54 +591 [debug] sess post disp:43703 2020/07/27 18:06:54 +591 [debug] pool:0x1c75880, del timer:0x1c75a30 2020/07/27 18:06:54 +591 [notice] del gc timer:1529025836970, p:43703 2020/07/27 18:06:54 +591 [notice] pool occupy:289792 2020/07/27 18:06:54 +591 [info] pl:29841536, p:43703 2020/07/27 18:06:54 +591 [debug] pool:0x1c75880, add timer:0x1c759f8 2020/07/27 18:06:54 +591 [info] nev:29841888,p:43703 2020/07/27 18:06:54 +591 [debug] pool:0x1c75880, add timer:0x1c75a48 2020/07/27 18:06:54 +591 [notice] session key:1529025836970, p:43703 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43703-->10.1.115.14:19611,len 146,seq=3465683027,ack=79264385 2020/07/27 18:06:54 +591 [info] ln:29842296, pkt:29842128, save:3465683027,p:43703 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1, p:43703 2020/07/27 18:06:54 +591 [debug] proc clt pack:43703 2020/07/27 18:06:54 +591 [debug] fake syn:43703 2020/07/27 18:06:54 +591 [debug] to bak:10.1.100.1:43703-->10.1.115.54:19621,len 44,seq=3465683026,ack=0 2020/07/27 18:06:54 +591 [info] rtt:1,p:43703 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43743-->10.1.115.14:19611,len 146,seq=1726534888,ack=2130674728 2020/07/27 18:06:54 +591 [info] ln:45053896, pkt:45053728, save:1726534888,p:43743 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1372, p:43743 2020/07/27 18:06:54 +591 [debug] proc clt pack:43743 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43743 2020/07/27 18:06:54 +591 [debug] lost pack, seq:1726404134, expect:1726404040,p:43743 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43731-->10.1.115.14:19611,len 146,seq=2032366102,ack=1658387931 2020/07/27 18:06:54 +591 [info] ln:45006760, pkt:45044664, save:2032366102,p:43731 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1339, p:43731 2020/07/27 18:06:54 +591 [debug] proc clt pack:43731 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43731 2020/07/27 18:06:54 +591 [debug] lost pack, seq:2032237980, expect:2032237886,p:43731 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43779-->10.1.115.14:19611,len 146,seq=1831914156,ack=1154999609 2020/07/27 18:06:54 +591 [info] ln:45052984, pkt:45052816, save:1831914156,p:43779 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1342, p:43779 2020/07/27 18:06:54 +591 [debug] proc clt pack:43779 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43779 2020/07/27 18:06:54 +591 [debug] lost pack, seq:1831785470, expect:1831785376,p:43779 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43759-->10.1.115.14:19611,len 146,seq=3550719133,ack=2053491967 2020/07/27 18:06:54 +591 [info] ln:45024280, pkt:45024112, save:3550719133,p:43759 2020/07/27 18:06:54 +591 [info] slide_win_packs size:1210, p:43759 2020/07/27 18:06:54 +591 [debug] proc clt pack:43759 2020/07/27 18:06:54 +591 [info] state:20, con len:94,p:43759 2020/07/27 18:06:54 +591 [debug] lost pack, seq:3550602855, expect:3550602761,p:43759 2020/07/27 18:06:54 +591 [debug] recv clt:10.1.100.1:43767-->10.1.115.14:19611,len 146,seq=827079725,ack=2949419059 2020/07/27 18:06:54 +591 [info] ln:45048992, pkt:45048824, save:827079725,p:43767

Q:这种情况应从什么方面排查呢?

部署情况: 通过tcpdump拷贝离线流量,一台tcpcopy节点作为回放机,一台intercept作为tcpcopy server

wangbin579 commented 4 years ago

tcpcopy单线程模型,需要把拆分数据包分而治之去回放,就可以

yumao123 commented 4 years ago

tcpcopy单线程模型,需要把拆分数据包分而治之去回放,就可以

请教下要具体要怎么分而治之呢?开多个tcpcopy实例按百分比回放同一份拷贝的流量么?