From c819bddbbb8b85f5c6c10fd4a163de4cc7d57f77 Mon Sep 17 00:00:00 2001 From: meiqi <976161896@qq.com> Date: Fri, 13 Mar 2026 19:58:29 +0800 Subject: [PATCH] log2json --- .gitignore | 3 + ikcp.o | Bin 22576 -> 0 bytes include/logger.h | 20 +++++ kcp_impl.o | Bin 6320 -> 0 bytes logger.o | Bin 5792 -> 0 bytes network.o | Bin 4240 -> 0 bytes src/apps/test_main.c | 161 +++++++++++++++++++++++++++++++++++++++ src/core/logger.c | 155 ++++++++++++++++++++++++++++++++++++- src/core/network.c | 14 +++- src/protocols/kcp_impl.c | 38 +++++++++ src/protocols/tcp_impl.c | 59 ++++++++++++++ tcp_impl.o | Bin 7912 -> 0 bytes udp_impl.o | Bin 4728 -> 0 bytes 13 files changed, 443 insertions(+), 7 deletions(-) create mode 100644 .gitignore delete mode 100644 ikcp.o delete mode 100644 kcp_impl.o delete mode 100644 logger.o delete mode 100644 network.o create mode 100644 src/apps/test_main.c delete mode 100644 tcp_impl.o delete mode 100644 udp_impl.o diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..9ce684e --- /dev/null +++ b/.gitignore @@ -0,0 +1,3 @@ +*.o +build/ +*.out diff --git a/ikcp.o b/ikcp.o deleted file mode 100644 index 43654d2b10679857136946cbf2efc1fa12a9e843..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 22576 zcmb_@e{>y3b^ppg64@kqBA7-HLzKh`cI6l)aZ@XH!b_|TYp|V%?UyFRK~^Lsb|cHG z^j;!U%T|yd)pik8X$AfsIOnUA^24-$;D(S0A1BC4$`gE(BJ(v=q&}ch7oLz#QHq-g zFm*qlJ9qZ&Tgz?_WRKqN%xCVsb7$txojbFu1MbFq=9QH>_9}Dkbc#8PI?j=8#dK1V zN#_dZa_1L`cmFEw`TyqiOjme**Q^&TWT}@M&RppQZ)HFXN+i5dEm}?z9jn}IiU10OxbdK~yQJl}Oc)w9mz`W-CVjD3s-FD)`5ZuWaeCU-Qlg_IDjV^~%7)9v{9z8zV`9~5 z_=Jy5C?O0>k{I;gBO}SWK{kYPXYx0+2cmuby_Uf*CQHzMOVHPU$R_<_vIHHp1bzL7 zZPG6$OVA^hps$}w86}I!5_DJz^2zN;32i>PqnK+VwL?-f#Hws=wMa{DB-v3GFz=^Qk@Pl0(n1oGYzvd(=9oJ=PfPvO zG9l_N5XLpcX|C1vPa|!LXIO^INW7oPqqJ$}{nS1_&}O@+X_k(Y7qgKG*E3E3Qov*? zlscC8(nv1oSV*2Y_-SZ9^$|!cz~By3IOip+4^R&*GT2h?`6;nvFG%7^>`G6kXg*ZP z%O}f?awLE_|NAuA2YyL^jcjN-VMVng**^=b77KcFtN!6^ShdBHdIiNmi{RJ;92xB)lz}$8f#datAWuq9miDYrgR7*G&b* zsaz;dWhCuXMsg=uXsv~OcVvndVA&Ha!6ns~Ol}xXzVI2;5e;6V;Zl&sn$ypzQM$w= zF$u=8#*F#tmjn0ZP+3ZgL*h zs-CWwoxStlc<5!c0ri^Y+II__S9=!^{TJz8#q2`!*Sat7Up(|1BBMaa5Tp=2;gMWd zJJNnB)a2aGyDy8j6sUFj?#$$3>MBdEOwAciP2iaDV@~EKlwj#u>C2kq^?6AEVlPeh{_gt>*+e} zWOtDKcXS)5Mcl@9|0za>{%Pt<(SeNnsU`*{87_w7-a<1V?o1;0WArqlI5cUkTSy$N zj1KJaqo0jt=LoLY(QJoxdx1D`)LU6QlF0pxC8#etT8SPmKEGRAIq=)VhHaN71^t6o zuJN}K6Pz{vmdY9;h6)Ih#MPqDEUW3SGRi}LiRQ`5zLWx$Qct)phfQZoUqdeny=8-4 zc3j=lHQ{95Zsd5f$StCoK{)O&m#jfGoPK$iOPmACj7_(1{Ex$MvFY|#remnEjJvKA z7$ihTi=fIZCcspi=qdUmU)eKUh9+Dp6LyNLc!Ygsiqi&u#H@8PBc?ecI1k7S>wlL} z=u{(jXmi;Y#one%+Mh!EN8x^k{q!;Gbpm%3OJ*!=|L2Q!MNii;IuCI&zcc~yXdnS3 zH%ylp=P?T3)N8tA6kQ@ojN!o_P%`QS*3V-42(%KdBMMDG)borI1+u2kpyO7I`03LD z{@i0A*gOIsrfhIs=oF6lsF{|{ufa;#Y3FTXesZx^8FKZB*J-o7pkK74(=Y}fX_p#& z*c4iNXz=J}%S!!4!5Q^@P;EFF^?p5F!%pTFu7bMrF&_uz}D$%uc>MPu1q%jT;k1$R`TH+);HBOrG!Z-=ZFirviZLk9KSd$zR zNu!D42j4k^-LzZq-3eO8f%3qenEV$zf*4Tu*nvfPcN~Z_bsfZwVpuVbWn+CFr}Jpg zR_>1;rN(c(?z`hd-AL8C0tb>XY2RBE3$tzqgXO> zQaz$)W9{0u?B$rc)$XaDLYY4@wNSbOT7nGTP~2z4u!@HGX4ocX+)m?rNBz`J(~w1M zg4h=lupr#aFt+ZgvcNsH)*VlL;wd;{3`E4Yz_0k(m-4QJP%>`GmGCLtXp9Ewm(bwA zeaRm={-I$XEJf$0z2m81s*#+OpBU)TMAu-pKLU`Ib=K4U|0a7V_kiD`}vr zi+|iCmLH!`(Lpi=SLLVA!1i&<1t+wAq-@l8$G*M;3oxUZAUzsvS?#A!!iN1#rvev= z39dsf92XL&g$Ircy(pH5#5AybM*6K%HPL91+a=EQaLdE_SMU}drkb_xOa{ggT^`ui z1wU0Wbp;baYKi8fGJB?zTmmpuC`6}MaBR|8Q%<4<)$U0QJ36ZOwXi3a2m#uF_RvHP zfzM&4grahV$uAlVv9Y*xDDKEmLdhVxtk!)g`!F>!z6g)d7a=Xa2v7Azh`u3Asz9>D z7g?wCg(-;z(1sl*MuGkAn0g;-U~QuH1bg0{sCG|_)}7a)5VMCWKy%xVg+%TiEM-#* z`mta}EV^e}q6I&D669Q#rQg9lDa$)sGG{{r7(hB!_5S^kfojobX*_%Y#on!+{4Rn6c~41gWW zp=g6Y8jfYj>82e^Gz6UEf$a4Ved(?uki(j_?sTH(Cb)sTd%7I$pPGN785VRJc>90i z>A|OP>(NkJ=Lx0N3E<51q+bEqI1fxMfV(kDn~|{Le?J{d zsjiSJ@r8#djI`NAcc(`H>6!itxCgc97zhZAQnBXSg1&gEG5g4awtoyrqG z!EW0z0rL=A#A?u86H}Y18B%mr6XG6qQmH3JJT=VaYHAG#3fAGprq_XYq7Xwy37Dq~ zhbX<)oya}~kHC;6+o1X!F#(=5S>s%!d9p15IQZFBhKkZ0;gdpX4+u$sc4Naxa~kqf z+b886N@;_C{%>gT4E3N!bM0!`cUTndt`;56Eh0M{=$o;tHA*t@q>@GtyETPJkp>TW z;Z6^bG!4oQirA9i9{Ar_|q+ICf0ceSVo1CREGyV|hnY$g5rX0gic->S%n6Fu^E|b2_ySUyhAL55JJO}w!Oe>hnG?b)QY$1~SN1$F zDkO5Xmm)C#5N_Z$t;%&mIj=8Q$%pTDqkxE5TQ_I1WEUvx`G(Et8C2la8Hj5~GFthG z@`z|moxa=xBXYYbeYiRUPN>=8D>9i?+d*b=J==8!8lJi{Oul12{;#}HZ!bBS{t2FGQF;|K^2 zn@K4ghskmHJdQ))SYkK^L2yVo28H7gIS!r2(F=|W!_g0dUg78$j$U%~Du)a*T>J_d zo?!_Kfj1jC$f(8IQ!X!$&_vqZ!Mrk3d@tR1<-=8t7dSXq$oboO0q4 zNPSLvKJgqn-q>#{84O6HH7|SA8{|M(2x$DDIdkq@M69Vik$Vm^FEFDL49MKtve6%? zL4WwU)wl;armH1wV#+(tCtoAv>x7)?>KxPFq2de^jgJ2Z=>Lg91TGFEW{`HoTFO~yg_j4O1 zO{7}VhP2X3r98_<7o(cKPz9Z+ZtK68m+94Vej?o+Bx}6J(et}01$JNJ(?DLIS4$cj zJgw`SDtm+ftquN|=f7s(1#4YJw>0@YJXK^gjddk*-=`lnefvU%D)`ETc)i=S5y!PM z>-;wOn5f|qvN9EGQfU$dXyX_M=wRH>77c8dE@HYm$F%fd!hZ*J3qXIgE|X#Icd$Am@Ww6 z5tkPXNTC@%4VN&6&Lktmupz@ojg!be0BL41EFJ+1;HNw-dLao;8tJ#tLyWmU&b(Hj z-x(-Lam1&ZB6S(>lYPGx*sTIPMPR13q~EAb#FmscB3Yf-)iez2Kg*;a!mRPGlYcu4 z6Byup3;H+%wSMzW$ujs61tb#KNivBC{9KEqiBwD4*v=>arZ_QzR9(oNWQ6r+k+NjD zpIce1FG{-%$JTd-oOKfUXn%(S``P9|B$U|+<_kFaJ@%ZASU1Vm3RwqU^_gKDV7-Re zLcOFj;u2pOhJna@}Q52sfAxhH)*x66(?Y%GtmpWf}mSFR$IZTq*W?Hn^bj*f~0=2 z6-3&z`08hge8Y79S3f<|JFs8D%AXx95*o$&yzV$tQZ2N40T`&~V4T(G(kcm9>*hPng?}4%JG#i&$*|>D@EDp#zc_f?gHe(Fm zV8Mi<-(WpCEjuH8{RR_jijSrQyFn6Pz^y?stjPHG?gN#gLt*HFmb-L z1S_PO{1k3buh*+~5Ba$ygqrXX)0G)<4r~oRPO2T*kEMjD7i>bCOe>A2yY~k~O)I@V zY)AXND)US&3%wG{N3!!oAyR(?KRSG}3=R)6m{4v17cB_e-Y~p3!8UIFr>Jd|4Exxx%&N?JN2E$fl2aFhhM!;o#p0!;-G&sk5oD#Nz*iZP3-~I_`T)MoGDPx*fU$rv z)EyRvAa@W^vFt`o8b{qPn-q*0%i_QqvF$3$l3dc~L6S^c{{wL9=|TVQWwumKc_0z1 zO_8_8mL_YsytBsDeB_gBj14fk&LmAMQaIS4;|*snR%a8>`vV!^CTyiv zUbe#8ki%H(Anij2q<=s|37T`U!#>wP9VycpfY=#_gVgFkmNjmsJSfSwyC|)h{Djya z#nk9<40K8>_Tg@hi>h->YghaT)&6f3xZi}V#wP9$^ewu-Kv;;w+wf@Dk2Y}ph1;sZ*ro?0B@HNN>y+%`DHb{s!Gc}>~qiP=z4 ztUt6L%v#Pqo$4}@*Q}Mje0!_Ou9M(V6zJynEm%nL(!^*a0A6&izi7u`G(($=j)-c| zBXI>HVIG7yiGyeD_}WQg<_-qUE(GSR8~`UoWbro&uQZ<+kLekJtoebQ0YnV{qVd4{ zPDC6o12;LIlEal#JVn7$uT^2O;kPsx5Az`gPSWHPG(-lG@A6GKKS48m5p&&#%>iDk zN_Xaym!St3iD1IXl+c3kHB^5h_s@(qN?P6XJfj+CKX%e{hc|6wJnE5sM&h6enauF< zO|F_&1tQ0RjgS+_>CA~jIO_6IuTm|Oub?DE;7X_55emdhVmx6_`?4Dm>nWy^<%zGr z&PAx%iuF8S!!~3dG#=`=tRCO28|R?SD=(=dY-=5+;&RPhoJCxp%Wcwy{yC!bWiH=D zF-GGTZitAp?_e^YY*UvtE&&`rAlqhW@JNpb2-CQY!vDC;RP*0l@api%uIa>k9Ou9y zBxc6Xo$E56p&8j=*H6v(O`yE%gk%+&lKDPY6|=s37Mq1?_pErd&Z|TRt8OVDV{{B~ z?2XxBKl^zw!P>WBAA>hV7_$R;cgQ@Bk--$R?d5^{dHHw~PrS_v+-IV1g71*#EtRq{ zDJy;`aEG+`5-EE|?&Crc{ZgP)#Qz;?lp=fufl9)c^4NP&k>cVqLoXWnrU7fFTM(XU zY)Gs5Sqj3%p01ai0}BC9rSS@Gtvl2OC0_FRLWy4=;XfWC~vd%8UF(jhF*=cZspr%_qKPc7ghNS6F324Kts?7H<|DloFQQHnr(=hQ!es%6U< zd0Axs>F3F=Grezfoc(w!D2b`dd%DgnI)HDY&S0zO1nDynGmC#25cWv(3_Hzw({vrW z8f;GIs*t{g`Ao&oyCH;*hB8)9T~Yeq3490Mx#G#L8LNUMsKSh>Fk@8Uh)@NY3zsv) z|Doxp`S#$YZl^*8zn@|4`HFH3@Lhm;1AH65<=wwH?9esxZCI83a|~bUqNem&?9v1G ztX-_pzw6GIIxC8p&nFN*mW@R^M}0<9d?PLg6*wKi_W<^#Yz4%abCm+#Y-5z?Iv_x^ zc(F72`S~b*{B($?)!cw{FT~9Voe;ft6@K0L@gH~)aS2Z)o=fm!Ie*-Kas$Wz-{@#> zd~aL(p3I)cJuMyY-St>w+p0zfcm8g=b5AzYmd!X1Zn^iNsvBCGsvh2(Y3^{^n;Rdm z>S(>=hL)_;(%f2g#~oE|&CQQ>?D}Z4VcXr&QFUikjnmQmsMFB+Sj(=COx3k_RBcXg z+z444Aj^t!cD15{DiGbS606!X8Axuza}S?N(blmuq{wtg)rJ+yKisTDPwZ;#xE+dS z9fvKcSM||MlW%WsX>RCfj^rC3X9kzhhpo_jM{}!u@^8zbW_??>W2fW1fBpK~tCpu9 z&bDTef{?H{F(%>@E9mS-q-e^{Sg!Xo1LIfO`dg?DO|;PIDZFiE)g0aeR1{ zeRPXc)>%<@^<|fq_hV3(0^^U@I^NtXDn34M{pFW*fB;#R36AF-_=V+}V)=IBxK{9H z`F9k{_Yuc+BX73+pl&?y$;x|26so-Oj9 zC64RoyxH=3KM?}*^8|$#oK>;>14VwR7eyaoXIlRG>G`()?aKeJH2$#s)p@pjpO#;T z;;{UIqWsTk`GFGokB9P)X}L^7D}UY_B0$=&<=Z*nwtW891-AaPTE3Ofu>1pI|1G87 zxH!+l@_8Q&<*(E7>Jt9zLjLVq{(}YWbI=x%{D|AU_&{LvHN>C7lb855JnzMi z_$WbK*PDmah$r#)s4a@G0=7r-X2r!v0sB+@xPsPbS6qfXufN2PcvA7p1$CS+DV|cC zrq1hm{7An;@hb#%od2)5>@JYD^pi+a&o5kQ2*qb0`AfxT#Yw8K0JaEnNxxAS81WIn z`M*TOpLjbmxPD+B&U+M3{hk5DCm?yd;_I(6xcCAjJ>b;88&6(V|BopBZy0>w65oL5 zV~W2^2SnyH@IO`j2sTE%YR$t5fWH;;?PV?Okm5FPpI=bi+Kt7ZR@{!0#rfYml+U%9 zm&IRE+^)+Oe^qg9R!Cn^oc@ZJrGH)VDnX0*0@xGlT^7TyRGjwC%gVV%@s$P+@s*0# z#PC|hIX`$=Iqz3|je$cvt+<^>mcCK(WQ_h#6t9cn^zm$$7sEfL_{JFil;Wuv{#C`d z#qgVuw_~M6@}RxUg?|%ru7ri|Rbq*Okp7DoFB^7|J=k$l%wRhjY8)-&R~=6O`2{zQH;k zZPymybG7RMORp2xt`&_Jpx>qRyWe3Hku@F3y^8-FdkbE&mg9L)@kyQ6vIYbH3&rbh zB{j|`&BOVu;_p?%l{FV-UsQbG9~itHm6@O6iFDv~kiZA#>1IU_+ z0guTO1pw{3f%{+{&a_1iYwyScu8)gL%> zp{wUaZ=DmpWlr>FQ**YhsUg!`kNuBoy0d*(>tpo~XCE>7wubhONU_OgTN|RKk2G{- zLIL4UYA&^F3>#@4ZO)iXb8F+CrsjI?D5YPXXl<&`wq`q;o16_FT%W4nvhCjb&2<}# znN1ru7c+J4J;ltXyY4rc^_%MIQ|YZic-E!YuD&pSz+%2Aamx`}L zYU75@s>n8Pi@VjU->`XuvMLZZHnrv6yWL2+$#2}S$uh83)@~r_N-^Gs%$|1BvoyEI zJK8Y7nMYs~GHCUUJ0Gimq+wSJfQF8a=Jt%q3ICr6tzm9#Z-$|mwB2nBQAcw|%~!HK zLNHX}o_lxm?#8yg29%9=!^3;pb@Yuv!3Nc$Wb1E8A8Fx+T!b1cHR;Bk&7rY2XLe_@ z21cWr+aGUeF}YTlR7-=_35${w3=#E2!>&vRHvf`=5jO5=eOzX~_2Y2+vUkUUylpR@GWlTFNxt+{!+!`{dr#m=N`tkYchg!jkNe$?ul{PdV5XQ*`#>9fBrQ_Z}tC= z7;g1H8^ixv*{=PwH-=mJJu%$&PoQ{QepcfgE5AkMAB^Ev{wHJj z=T-ktD;}5s!Gs}*%l~i;xAL1}_}{Di7RBT8e;UD~<9L+@cchQv*|*NE&%qdO_4#BB zxB7fq@wh%GB6zgkXRa!(cc1q2i!t2R`$`P|n)bu@6pz>YY6QOvwAP-xbOUDl{~uJ& zUnovF(fPjQT0>yzPb&S5ipS~q$LL>I`u+>h|LQtJKsnL=dE50x{B9(z{%wj|eG+Ac z?qd=9sQ%xM(O<3fr!GK$)s4k^|1eVT-)ekLJ)?Nb%|-gC{&#BJ9;aWvx=3Fak^lcF z6jz+SN>Jl}*k*erH9?F&yD!}l!>vE>j^R&felUiQYJNC|PicN4hTHQXY{BHR`q=ZJ zsu*tfd&wAX_j@~HxZUq{$8fvf8;s$0zc(Di?S5|}j;o)NPDBf={`UN+ia-Rn=SRsH zZqJW)#Bh6l)E&d^`O#nux93O0G2EULO~i1!&$KT}Sj?Z@XI9Op_QiJDbERYqx93Vb zVz}LxcE@nLFCC2Gc3(Oi!|lFwB8J<2sTh7lPrEOz;)ICcc3+x|;dWoTBZk|3sk5qM z@9s>)!+2)e&2y(sArNm^m1*wGIIARtUiENChqJ1EkI6Ld+0AXJv#NDZrg;_KP2FVn zX(s<@Yjzc0v9%%O-wPf}YTjA@NPEL>d5vb2{~hjC;HAlG7!^uNYU+gg4O^h*ZLO7m3f4BE6zUeMu|;_L`a-e{wT(DoR;sP z*~M}F$CbYdWzj3H{~x1}GUNQS%HOH>Ze_&zX@zr*|4hnocsei~e}>+c-;V!Wb(6DA vUjVF8`(e1s5F*Y`nenj)-x>{!GLkFa;{5*&Z~Ph9 diff --git a/include/logger.h b/include/logger.h index a8ea804..36fdb1b 100644 --- a/include/logger.h +++ b/include/logger.h @@ -26,6 +26,20 @@ typedef struct OmniStats { uint64_t tcp_retrans; /* 预留：TCP 重传统计（如可从内核获取） */ uint64_t udp_retrans; /* UDP 上层重传次数 */ uint64_t kcp_retrans; /* KCP 内部重传次数（可从 ikcp 统计） */ + + /* 延迟/耗时统计（单位：毫秒） */ + double send_call_avg_ms; /* omni_send 平均耗时（EWMA） */ + double recv_call_avg_ms; /* omni_recv 平均耗时（EWMA） */ + double proto_send_avg_ms; /* 协议 send() 平均耗时（EWMA） */ + double proto_recv_avg_ms; /* 协议 recv() 平均耗时（EWMA） */ + + uint64_t send_call_min_ms; + uint64_t send_call_max_ms; + uint64_t recv_call_min_ms; + uint64_t recv_call_max_ms; + + uint64_t last_send_call_ms; + uint64_t last_recv_call_ms; } OmniStats; /* 初始化统计模块，在程序启动时调用一次 */ @@ -41,6 +55,12 @@ void logger_on_rtt(uint64_t rtt_ms); /* 记录 KCP 重传次数变化（可在 KCP 更新循环中调用） */ void logger_on_kcp_retrans(uint64_t delta); +/* 记录一次耗时（ms） */ +void logger_on_send_call_latency(uint64_t ms); +void logger_on_recv_call_latency(uint64_t ms); +void logger_on_proto_send_latency(uint64_t ms); +void logger_on_proto_recv_latency(uint64_t ms); + /* 计算当前吞吐量（返回：字节/秒） */ double logger_calculate_throughput(void); diff --git a/kcp_impl.o b/kcp_impl.o deleted file mode 100644 index c0883c522c950fe5937d93ea83354533ae048f7b..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 6320 zcmbuDeQX>@6~M4bOb+o;>2kT-a}M9# z9(Q}xuIe`QaMjUrB?uW+6rm^zl@St+ikdi9n_d#Bb|e(J`~jAzz@UO$9Dxx*Tn*)T zZ+6~gyuKv~jI=j1zc=q=-p;;V`&ncEp2mg-My-K$vg6p zc=2i=&YkA%_k(~7qta34C1Z|@x8Fij^SGQl0FsOIO*rhC=aawQdFEHo{bp-77t{P7 zf8rOGZo|=q%4hil7rB_>4U60fSK|Cro26NMl{9nt(%)L|SyE2hxfq!jh4;7!&vMZ- z13qTJJt!KB4&RI&FAX(2#(O-5!bJys7v{Uf<$a=Z4xov zYyIZWz&_r;$u@Ke7u-{KX=2KlYhYQePSUF*s+E7R${m!$wJBD%31PKUFglhI_GlHH1IzhCl8JAI{&5 z*xiEKQ=!e63>-S)Y0(BLI39{@b>GtbBqWIN*I- z!2c{S-TuM9s#Wkw;Uevtz$fh-9*xO$@N*ug`hv-0Nb!eg>)D=D?&ep6h4FB^D_O$%$mge33*ly@J zp_>cIbJ%EkNTw0$w_BemBsdCeq2c)DODu0@;SZhH@e8B~liGI%e`Mz8sXr}|mLP+P;+^=n#=LowL~QoOKz4S%{e zwmsk2yY1{vtenSER^DXr8yk!an6{lvn=BH^+fkUu zjth1`a z&?sd_VVjS4_eJ{pdk^(SzHq2(_kIHs_(_#Ue7rvb7kui;HmGr|F~l!ue1pc{(fCG< zQw_u~Mf5>-{;1Xy|EQWTdib4c{-Ns8Mk`!orx(rzHspBzh!1Ielg6LdxE|+s6sLIZ z1|4iKdpO1UBM+xIU(@XCamo*5u!nKp1{cNozP2816JOFez9Wfm!T_P6o!j9e-l6e3 zH2$c@_5B)(V~4hO!iBBZ!)d=?@^IR3LUFXA?>DP)TuX62t#LgMCp50-;dPDcd6?0- zo`-en!vf>McOCiNrZ}phY#&_M?(=ZkZ@Y)nes^j1_5JSExW3=dYh2&&vl{;x#6fYM z(D+>%Kcn%j8o#1A?du7UVf&qj$6d@8Je>CXcMpG2t#8C+LBmep?_C<#>%)M?w}B4r z>lKaTvqii`eJ7y!9*y6vaozr~#y_sDe^GJD!*@Z3?IjPV{hsu2y1%b#_VxX?t5*-k z8Gwu8FKYY~8vnk=_4DwG#`W_6sa9C+#{xBr+Px(6t4E?vmrMI&3AJid?DSy;|S!4Rr zKP!Em;h6M@e-#F}bVdGr_D}JX{&O%un_m4kwXi}9Rqxfuzn|*mZ%E~DT`pmll@=9$9Z4E6N`_%Q+PTW(kT_3Hlz DGZ9cN diff --git a/logger.o b/logger.o deleted file mode 100644 index 817727490fddd39680c775bbacaccfb72898bee5..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 5792 zcmb_feQaA-6~9ipHeJ^`E!*hSGFe)K>Wx}y8>Z1U!=ZC~hmx(d7=qT$b?q0?}L zxul4cu*|S0*CGJ{B_-h~`O`3o)QRbGZEt&=yLZfJCgrNzujxB@%)>H`Rci%nn z>y0Drj~(gx-1|G9_uTXDef~ylaDPW2AeaK;KGB*nDn#fbt#MQhqhf0W#Rt{PC6RRXf}jZO@Q8uIzq`hN2JM_=EvPr8@of8LVk z-`|AM`R1o(_=0q2Wnf-bt^NFxk0)4)i3`Uy#0LyZ9KZTxOjAF`us2j`Gty9 zyFoGclCo&LM0(Qou&Nd*Hq)|}?qpL|Z&7yDSW^aO4U6e|KqDWL6$QCIr+Z_~(mILY z9{xe%_;qLx8gu`{QezFN*IA7>R5j!Ca(Z%Jlvj@g->qMrq$u;UQlD6d>4FU2S-*Ol zbT7zP-kP2Z$h8+3zOWD+t}g_;*P|{A!AH(71UFKCTqm!VRH_f|>XBHpwS#CIDtx06 z_R=QLae65Inu;jhUrYDWa|o_>a;9ZE@cF}J-AmS&8(06U7CqZq^sKk&E6Qp_22a(g zD03`V^`RitA2zkdVD)2&FzBsnu&P22asfZ-$$G$~r%9!}ES%Mp=;fESQ^A8Uk z@wMkS-^NQR-E*5&Gyk|-u`^wY)kd)lw=%9+ZGzZibte=I$EJeep_yPfel{3B`b;ov z)q~;uY%pA&3x+4>eQ#_A*;2w6U$~J2%n*ph(K+HBPs`4c!_-7{)X*E@Z9VU@+a=xME)$fL+VJLODE0C1 z_GKvb=kPtt&?upjUn2M5K`-`EdNC;JW#p9ldvdvQNQ_%{wwTVQv_{T4VdeTCcyRwi zp;R$HUMyGzr=N62LQXQ%-%|=%x#W1sN+;qu9e>*iyr@q}$TcCz5*bEC*u z1FtZ` z3~K?|t)i!!9vo5!9*m0)A?m>B{!w(Z=7Fyr5`l^Cz?PfVbj{E^wv})^ps(O(U_KvI$>mi$TJL@UXE?uo@N zaJJ93?Ek3c+x+r}Tk>mK{;Xf#@k6Dsm9VWinTYPi5Bs-0`w&5UwftSb{J`nX=~W$n zf);!n(>h1M*+=K$0OTQprnLOKG+vSqOm}v;UL3&f2xhCqKNj1`I&nz0p-$Be*9&k$ zbolhuUK4gJJprFSJ}W@jYv{9{+IuBIPpPX=&pdX!*56Hy2U4{p9-#+)Y0_Q-+TlZl zZ=$$U+CcRbjlV=sJN;vXLtlLg(OC5m@uJ4xBMxHx6pf*Or!Jl9DZ)-`Tu-l3;mKF9<93%U-fX9#<31^qX){!#s+a{Rxqp#Sd`aP&Ch{tPcYk?J!H za>Y!>vLh)`%onnWLh-9~WQk0o>Bu^%WG+?CB^@i#I(b>BVvS(?G#IBIf+t%ZimsLv$U@$(^`72(Par5L#>E_ z<6U9=3_v1mC$@<3rvMT`|0a4E{{cWEQ~wzcUWWhF!1eZtmkk^-K2G0HSR|Drdykp>8w+3QA2`8#0F z!1*4gD^(Hu;qQQuf%A7y)WG>WAZ_4$-#=#He1D5b>15tX9w+YD9v|hAP5*Twjy2(k zNIK~xMdWy?BqDavo6tXsJpJntkwVe2BJ^Kihq}e}JX0t~#_b~ArOrvRfhTJ;F=8j_ zzW*>NL{6}z)rPaEo)7ANV6k34PsJ7*p;ey7ex{NQ-eNE4{&`P z08(_?h|9PcAN>!Xru|uM&)>&vAL4=LJBh<5`o&Ld-(>{k{8{%?G=NGk1DZdr3ySY) zKe0RJpCKWS{d%vO8={4#?jgc)ewz7T(e@#2$IQ(C%OrqL)4r+g&l&+udy8z_?f>Jr zB#A=W9{Z2)H@4^fZxq}k5?XndM HP5b`?qZ%QU diff --git a/network.o b/network.o deleted file mode 100644 index 782c1c73a347e9e77148750241e4bdf81147c3a5..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 4240 zcmc&%U1%It6h52uC$(v^ErP9;vIs4$*fB|q)z--7XPYS|O<1z^Mcr;TlXmUyOq`u* zo7&WrpfC(d5g$aP=!+Bt9|TRGY-+`%5;WD92tkBmiN=RieFz#7&zZSrcD(FDtPdWT zx#xc8|DJpA?7oudJX{rt08<2>hSH2tfas0Q8P!QmJCmJGV!Yk? zYQRZMIn(%_oFjcVG2=|kU0hjNQJut`IyyWDR;}tH>w@~~xP5>Wu8SC|^LfC18E_L` zV9%S!{rnhK{n=J@evQia1n7JLoiBjh6xglG*KPEG=`6UZ87Jy9vrf+%;#4;^r#d|~ zlx?S5Q$IF5SwEJVQr)g`)wQSH#B7VR=uEV%+`{OK7=01!_`fR0i-OC8Ie=H%{IeqP zA_k6PG>m9Zxm~m97T3Eb+2Y)7aVA&4VCv`>UR5{4ZEH}SVXVyl5gUhYsUg!Ndpb4eG@BGPZDjh$WpQ@lDV_dU3nZ+t(^B$8@k97pT)%ieDk=yMQf5?1(e& z+*)m?$l#s}h|(@ATL3K#)%-sc5XBDoJI2aTb-eNif{7d7O0C!>0II^;R+9E?4Ft}_ z%D2Hv1}hz``h4Wl%^S4Aps3}wtd%}(W%}}3dLWa_YyGi7)3A)@o&BI|))~V*1&L&` zI|{A-{K5l!{rVCB`m4^LF;~pWv+}Gd}#fL7yj-x540vIQ( z8Xuzj{Q)B9k`Or?jcl)7Uvmj>pob8rhp2;IiMr@(Rc)KrT|fn#lI$tMk;dr8VtMsP z5z-*}b0kE%PA`^MUG*H0{5;`EmE`aGVtARxz~1x|5Hfk7RMx=V6&a^_b(t^AM#QT^ zxL2z%uJ%?%O*#D!5hwi-vBA9FA@*qneLkW}_Mb-?dfR%^J<0Cg z?)0(Vme$S$q}nCm8CfGZqmVaFoWS!(2by_=#03BYrlysSBP$qsnoeiw5QYSFCVfFR zZxl6_44OIJN)Kx0fMFIgdR9wQ6pwcM1D!W-7cJqJhNv-wuS1^kgCTr<2!Bc7bY?e% z@XG=x|0H8SS0wyFG5=V?9~Sd#Vk95;;lqArLO7if#(xnw$K^WzkZ_K>Ea4n?qu76P z+=9T_f2*)RBjN1-qJ*>mH!AplCxq9cZ?5Yb$xpwC`@Mv7+}jfVzR+I~xLntHDhP@2 zI(#_pTLPznWFO!|bXmeV?iC65zk&dt2waZaEY2a}bY3}bO5hy#CIv-GOE|~PN%#$4 z9Zm~ej{Ae8e@E!w3F&V^jPv;|gopbQ6LyrRDA7aW63+MNaS7*pZbZWQK6_8X`Q8Gh zI8?wN6*yX^Kb~aH)bbgHem;QGpRqEa^c9Psn1(;e8ij(Uqf9p}O~G&O-lCPso)YsD zx~<@^4ZJg~A+#Y++R5~QnJH)@lm9lv(44j)-7R5?i^*SNomnQfD^FoNa@5OsfcVS| zee{u3VNZ7g*$Nowp9|40d!aj@t{x71Ce9HDC z!ruEw7IGllYbYz%{}>%gq_h42)PMROu|4;{Tx>FVLTt!MQ82lqlw^DIDfb?sK=C_o XQhLejw;4s{?B5po)9<1%$@YH(BvU(d diff --git a/src/apps/test_main.c b/src/apps/test_main.c new file mode 100644 index 0000000..0aa63af --- /dev/null +++ b/src/apps/test_main.c @@ -0,0 +1,161 @@ +/* + * test_main.c + * 简单测试程序：客户端/服务端双向传输 + 日志观测 + * + * 使用方式示例（同一机器上，两个终端）： + * 终端1：./omni_test -r server -p tcp -P 9000 + * 终端2：./omni_test -r client -p tcp -P 9000 -H 127.0.0.1 + * + * 协议可选：tcp / udp / kcp + */ + +#include "common.h" +#include "network.h" +#include "logger.h" + +#include +#include +#include +#include + +static void usage(const char *prog) +{ + fprintf(stderr, + "Usage:\n" + " %s -r server -p tcp|udp|kcp -P \n" + " %s -r client -p tcp|udp|kcp -P -H \n", + prog, prog); +} + +static OmniProtocol parse_proto(const char *s) +{ + if (strcmp(s, "tcp") == 0) return OMNI_PROTO_TCP; + if (strcmp(s, "udp") == 0) return OMNI_PROTO_UDP; + if (strcmp(s, "kcp") == 0) return OMNI_PROTO_KCP; + return OMNI_PROTO_TCP; +} + +static void run_server(OmniProtocol proto, uint16_t port) +{ + OmniContext *ctx = omni_init(OMNI_ROLE_SERVER, proto, + NULL, port, + NULL, 0); + if (!ctx) { + fprintf(stderr, "server: omni_init failed\n"); + return; + } + + logger_log("INFO", "test", "server_started proto=%d port=%u", + (int)proto, (unsigned)port); + + char buf[4096]; + for (;;) { + ssize_t n = omni_recv(ctx, buf, sizeof(buf)); + if (n <= 0) { + logger_log("INFO", "test", "server_recv_end n=%zd", n); + break; + } + logger_log("INFO", "test", "server_recv bytes=%zd", n); + + /* 简单 echo 回客户端，验证双向通信 */ + ssize_t m = omni_send(ctx, buf, (size_t)n); + logger_log("INFO", "test", "server_echo bytes=%zd", m); + } + + omni_close(ctx); +} + +static void run_client(OmniProtocol proto, const char *host, uint16_t port) +{ + if (!host) { + fprintf(stderr, "client: host is required\n"); + return; + } + + OmniContext *ctx = omni_init(OMNI_ROLE_CLIENT, proto, + NULL, 0, + host, port); + if (!ctx) { + fprintf(stderr, "client: omni_init failed\n"); + return; + } + + logger_log("INFO", "test", "client_started proto=%d host=%s port=%u", + (int)proto, host, (unsigned)port); + + char send_buf[2048]; + char recv_buf[4096]; + + for (int i = 0; i < 100; ++i) { + int len = snprintf(send_buf, sizeof(send_buf), + "msg=%d time_ms=%llu payload_size=%zu", + i, + (unsigned long long)omni_now_ms(), + sizeof(send_buf)); + + ssize_t n = omni_send(ctx, send_buf, (size_t)len); + logger_log("INFO", "test", "client_send i=%d bytes=%zd", i, n); + if (n <= 0) break; + + ssize_t m = omni_recv(ctx, recv_buf, sizeof(recv_buf)); + if (m <= 0) { + logger_log("INFO", "test", "client_recv_end i=%d bytes=%zd", i, m); + break; + } + logger_log("INFO", "test", + "client_recv_echo i=%d bytes=%zd first_bytes=\"%.32s\"", + i, m, recv_buf); + + usleep(10 * 1000); /* 10ms 间隔，模拟稳定流量 */ + } + + omni_close(ctx); +} + +int main(int argc, char **argv) +{ + const char *role_str = NULL; + const char *proto_str = "tcp"; + const char *host = NULL; + int port = 0; + + int opt; + while ((opt = getopt(argc, argv, "r:p:P:H:")) != -1) { + switch (opt) { + case 'r': + role_str = optarg; + break; + case 'p': + proto_str = optarg; + break; + case 'P': + port = atoi(optarg); + break; + case 'H': + host = optarg; + break; + default: + usage(argv[0]); + return 1; + } + } + + if (!role_str || port <= 0) { + usage(argv[0]); + return 1; + } + + OmniProtocol proto = parse_proto(proto_str); + + if (strcmp(role_str, "server") == 0) { + run_server(proto, (uint16_t)port); + } else if (strcmp(role_str, "client") == 0) { + run_client(proto, host, (uint16_t)port); + } else { + usage(argv[0]); + return 1; + } + + return 0; +} + diff --git a/src/core/logger.c b/src/core/logger.c index 676d478..d283afb 100644 --- a/src/core/logger.c +++ b/src/core/logger.c @@ -9,19 +9,36 @@ #include #include #include +#include static OmniStats g_stats; +static FILE *g_json_fp = NULL; static uint64_t now_ms(void) { return omni_now_ms(); } +static void ewma_update(double *avg, double sample, double alpha) +{ + if (*avg <= 0.0) { + *avg = sample; + return; + } + *avg = (*avg) * (1.0 - alpha) + sample * alpha; +} + void logger_init(void) { memset(&g_stats, 0, sizeof(g_stats)); g_stats.start_ms = now_ms(); g_stats.last_report_ms = g_stats.start_ms; + g_stats.send_call_min_ms = UINT64_MAX; + g_stats.recv_call_min_ms = UINT64_MAX; + + if (!g_json_fp) { + g_json_fp = fopen("omni_logs.jsonl", "a"); + } } void logger_on_send(size_t bytes) @@ -49,6 +66,32 @@ void logger_on_kcp_retrans(uint64_t delta) g_stats.kcp_retrans += delta; } +void logger_on_send_call_latency(uint64_t ms) +{ + g_stats.last_send_call_ms = ms; + if (ms < g_stats.send_call_min_ms) g_stats.send_call_min_ms = ms; + if (ms > g_stats.send_call_max_ms) g_stats.send_call_max_ms = ms; + ewma_update(&g_stats.send_call_avg_ms, (double)ms, 0.2); +} + +void logger_on_recv_call_latency(uint64_t ms) +{ + g_stats.last_recv_call_ms = ms; + if (ms < g_stats.recv_call_min_ms) g_stats.recv_call_min_ms = ms; + if (ms > g_stats.recv_call_max_ms) g_stats.recv_call_max_ms = ms; + ewma_update(&g_stats.recv_call_avg_ms, (double)ms, 0.2); +} + +void logger_on_proto_send_latency(uint64_t ms) +{ + ewma_update(&g_stats.proto_send_avg_ms, (double)ms, 0.2); +} + +void logger_on_proto_recv_latency(uint64_t ms) +{ + ewma_update(&g_stats.proto_recv_avg_ms, (double)ms, 0.2); +} + double logger_calculate_throughput(void) { uint64_t now = now_ms(); @@ -66,6 +109,30 @@ static void print_timestamp(FILE *fp) fprintf(fp, "ts=%llu ", (unsigned long long)ms); } +static void json_escape(const char *src, char *dst, size_t dst_sz) +{ + size_t j = 0; + for (size_t i = 0; src[i] && j + 2 < dst_sz; ++i) { + unsigned char c = (unsigned char)src[i]; + if (c == '\\' || c == '\"') { + dst[j++] = '\\'; + dst[j++] = (char)c; + } else if (c == '\n') { + dst[j++] = '\\'; + dst[j++] = 'n'; + } else if (c == '\r') { + dst[j++] = '\\'; + dst[j++] = 'r'; + } else if (c == '\t') { + dst[j++] = '\\'; + dst[j++] = 't'; + } else { + dst[j++] = (char)c; + } + } + dst[j] = '\0'; +} + void logger_print_performance_log(const char *tag) { uint64_t now = now_ms(); @@ -79,6 +146,9 @@ void logger_print_performance_log(const char *tag) "elapsed_ms=%llu bytes_sent=%llu bytes_recv=%llu " "send_count=%llu recv_count=%llu " "throughput_bytes_per_sec=%.2f " + "send_call_last_ms=%llu send_call_min_ms=%llu send_call_max_ms=%llu send_call_avg_ms=%.3f " + "recv_call_last_ms=%llu recv_call_min_ms=%llu recv_call_max_ms=%llu recv_call_avg_ms=%.3f " + "proto_send_avg_ms=%.3f proto_recv_avg_ms=%.3f " "last_rtt_ms=%llu max_rtt_ms=%llu " "kcp_retrans=%llu\n", tag ? tag : "periodic", @@ -88,27 +158,106 @@ void logger_print_performance_log(const char *tag) (unsigned long long)g_stats.send_count, (unsigned long long)g_stats.recv_count, thr, + (unsigned long long)g_stats.last_send_call_ms, + (unsigned long long)((g_stats.send_call_min_ms == UINT64_MAX) ? 0 : g_stats.send_call_min_ms), + (unsigned long long)g_stats.send_call_max_ms, + g_stats.send_call_avg_ms, + (unsigned long long)g_stats.last_recv_call_ms, + (unsigned long long)((g_stats.recv_call_min_ms == UINT64_MAX) ? 0 : g_stats.recv_call_min_ms), + (unsigned long long)g_stats.recv_call_max_ms, + g_stats.recv_call_avg_ms, + g_stats.proto_send_avg_ms, + g_stats.proto_recv_avg_ms, (unsigned long long)g_stats.last_rtt_ms, (unsigned long long)g_stats.max_rtt_ms, (unsigned long long)g_stats.kcp_retrans); g_stats.last_report_ms = now; + + if (g_json_fp) { + fprintf(g_json_fp, + "{\"ts_ms\":%llu," + "\"level\":\"INFO\"," + "\"component\":\"perf\"," + "\"tag\":\"%s\"," + "\"elapsed_ms\":%llu," + "\"bytes_sent\":%llu," + "\"bytes_recv\":%llu," + "\"send_count\":%llu," + "\"recv_count\":%llu," + "\"throughput_bytes_per_sec\":%.6f," + "\"send_call_last_ms\":%llu," + "\"send_call_min_ms\":%llu," + "\"send_call_max_ms\":%llu," + "\"send_call_avg_ms\":%.6f," + "\"recv_call_last_ms\":%llu," + "\"recv_call_min_ms\":%llu," + "\"recv_call_max_ms\":%llu," + "\"recv_call_avg_ms\":%.6f," + "\"proto_send_avg_ms\":%.6f," + "\"proto_recv_avg_ms\":%.6f," + "\"last_rtt_ms\":%llu," + "\"max_rtt_ms\":%llu," + "\"kcp_retrans\":%llu}\n", + (unsigned long long)now, + tag ? tag : "periodic", + (unsigned long long)elapsed_ms, + (unsigned long long)g_stats.bytes_sent, + (unsigned long long)g_stats.bytes_recv, + (unsigned long long)g_stats.send_count, + (unsigned long long)g_stats.recv_count, + thr, + (unsigned long long)g_stats.last_send_call_ms, + (unsigned long long)((g_stats.send_call_min_ms == UINT64_MAX) ? 0 : g_stats.send_call_min_ms), + (unsigned long long)g_stats.send_call_max_ms, + g_stats.send_call_avg_ms, + (unsigned long long)g_stats.last_recv_call_ms, + (unsigned long long)((g_stats.recv_call_min_ms == UINT64_MAX) ? 0 : g_stats.recv_call_min_ms), + (unsigned long long)g_stats.recv_call_max_ms, + g_stats.recv_call_avg_ms, + g_stats.proto_send_avg_ms, + g_stats.proto_recv_avg_ms, + (unsigned long long)g_stats.last_rtt_ms, + (unsigned long long)g_stats.max_rtt_ms, + (unsigned long long)g_stats.kcp_retrans); + fflush(g_json_fp); + } } void logger_log(const char *level, const char *component, const char *fmt, ...) { + const char *lvl = level ? level : "INFO"; + const char *comp = component ? component : "general"; + FILE *fp = stderr; print_timestamp(fp); - fprintf(fp, "level=%s component=%s ", level ? level : "INFO", - component ? component : "general"); + fprintf(fp, "level=%s component=%s ", lvl, comp); + char msg_buf[1024]; va_list ap; va_start(ap, fmt); - vfprintf(fp, fmt, ap); + vsnprintf(msg_buf, sizeof(msg_buf), fmt, ap); va_end(ap); + fputs(msg_buf, fp); fputc('\n', fp); + + if (g_json_fp) { + char esc_buf[2048]; + json_escape(msg_buf, esc_buf, sizeof(esc_buf)); + uint64_t ts = now_ms(); + fprintf(g_json_fp, + "{\"ts_ms\":%llu," + "\"level\":\"%s\"," + "\"component\":\"%s\"," + "\"message\":\"%s\"}\n", + (unsigned long long)ts, + lvl, + comp, + esc_buf); + fflush(g_json_fp); + } } OmniStats logger_get_snapshot(void) diff --git a/src/core/network.c b/src/core/network.c index e7493a0..b71618a 100644 --- a/src/core/network.c +++ b/src/core/network.c @@ -87,12 +87,15 @@ ssize_t omni_send(OmniContext *ctx, const void *buf, size_t len) return OMNI_ERR_PARAM; } + uint64_t t0 = omni_now_ms(); ssize_t n = ctx->vt->send((OmniContext *)ctx->impl, buf, len); + uint64_t t1 = omni_now_ms(); + logger_on_send_call_latency(t1 - t0); if (n > 0) { logger_on_send((size_t)n); } - logger_log("DEBUG", "network", "omni_send proto=%d bytes=%zd", - (int)ctx->proto, n); + logger_log("DEBUG", "network", "omni_send proto=%d bytes=%zd call_ms=%llu", + (int)ctx->proto, n, (unsigned long long)(t1 - t0)); return n; } @@ -102,12 +105,15 @@ ssize_t omni_recv(OmniContext *ctx, void *buf, size_t len) return OMNI_ERR_PARAM; } + uint64_t t0 = omni_now_ms(); ssize_t n = ctx->vt->recv((OmniContext *)ctx->impl, buf, len); + uint64_t t1 = omni_now_ms(); + logger_on_recv_call_latency(t1 - t0); if (n > 0) { logger_on_recv((size_t)n); } - logger_log("DEBUG", "network", "omni_recv proto=%d bytes=%zd", - (int)ctx->proto, n); + logger_log("DEBUG", "network", "omni_recv proto=%d bytes=%zd call_ms=%llu", + (int)ctx->proto, n, (unsigned long long)(t1 - t0)); return n; } diff --git a/src/protocols/kcp_impl.c b/src/protocols/kcp_impl.c index 6b254eb..0e838d5 100644 --- a/src/protocols/kcp_impl.c +++ b/src/protocols/kcp_impl.c @@ -22,6 +22,7 @@ struct KcpContext { struct sockaddr_in peer_addr; socklen_t peer_len; ikcpcb *kcp; + uint32_t last_xmit; /* 用于推算重传/发送次数变化 */ }; static int kcp_output(const char *buf, int len, ikcpcb *kcp, void *user) @@ -104,6 +105,7 @@ static OmniContext *kcp_init(OmniRole role, static void kcp_update_loop(struct KcpContext *ctx) { + uint64_t t0 = omni_now_ms(); IUINT32 current = (IUINT32)omni_now_ms(); ikcp_update(ctx->kcp, current); @@ -117,6 +119,32 @@ static void kcp_update_loop(struct KcpContext *ctx) ctx->peer_len = fromlen; ikcp_input(ctx->kcp, buf, (long)n); } + + /* KCP 内部状态监控 */ + uint32_t xmit = ctx->kcp->xmit; + if (xmit >= ctx->last_xmit) { + logger_on_kcp_retrans((uint64_t)(xmit - ctx->last_xmit)); + } + ctx->last_xmit = xmit; + + uint64_t t1 = omni_now_ms(); + logger_log("DEBUG", "kcp", + "update ms=%llu cwnd=%u ssthresh=%u rmt_wnd=%u snd_wnd=%u rcv_wnd=%u " + "rx_srtt=%u rx_rto=%u nsnd_buf=%u nsnd_que=%u nrcv_buf=%u nrcv_que=%u xmit=%u state=%u", + (unsigned long long)(t1 - t0), + (unsigned)ctx->kcp->cwnd, + (unsigned)ctx->kcp->ssthresh, + (unsigned)ctx->kcp->rmt_wnd, + (unsigned)ctx->kcp->snd_wnd, + (unsigned)ctx->kcp->rcv_wnd, + (unsigned)ctx->kcp->rx_srtt, + (unsigned)ctx->kcp->rx_rto, + (unsigned)ctx->kcp->nsnd_buf, + (unsigned)ctx->kcp->nsnd_que, + (unsigned)ctx->kcp->nrcv_buf, + (unsigned)ctx->kcp->nrcv_que, + (unsigned)ctx->kcp->xmit, + (unsigned)ctx->kcp->state); } static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len) @@ -124,6 +152,7 @@ static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len) struct KcpContext *ctx = (struct KcpContext *)c; if (!ctx || !ctx->kcp) return OMNI_ERR_PARAM; + uint64_t t0 = omni_now_ms(); int rc = ikcp_send(ctx->kcp, (const char *)buf, (int)len); if (rc < 0) { logger_log("ERROR", "kcp", "ikcp_send_failed rc=%d", rc); @@ -132,6 +161,10 @@ static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len) /* 驱动一次 flush */ kcp_update_loop(ctx); + uint64_t t1 = omni_now_ms(); + logger_on_proto_send_latency(t1 - t0); + logger_log("DEBUG", "kcp", "send payload_bytes=%zu proto_ms=%llu waitsnd=%d", + len, (unsigned long long)(t1 - t0), ikcp_waitsnd(ctx->kcp)); return (ssize_t)len; } @@ -140,12 +173,17 @@ static ssize_t kcp_recv(OmniContext *c, void *buf, size_t len) struct KcpContext *ctx = (struct KcpContext *)c; if (!ctx || !ctx->kcp) return OMNI_ERR_PARAM; + uint64_t t0 = omni_now_ms(); kcp_update_loop(ctx); int n = ikcp_recv(ctx->kcp, (char *)buf, (int)len); if (n < 0) { return 0; /* 暂无数据 */ } + uint64_t t1 = omni_now_ms(); + logger_on_proto_recv_latency(t1 - t0); + logger_log("DEBUG", "kcp", "recv payload_bytes=%d proto_ms=%llu", + n, (unsigned long long)(t1 - t0)); return (ssize_t)n; } diff --git a/src/protocols/tcp_impl.c b/src/protocols/tcp_impl.c index 3c7f60f..b0278aa 100644 --- a/src/protocols/tcp_impl.c +++ b/src/protocols/tcp_impl.c @@ -10,6 +10,7 @@ #include #include #include +#include #include #include #include @@ -17,10 +18,52 @@ #include #include +/* Linux 下 TCP_INFO 定义通常已在 提供，避免引入 重定义 */ + struct TcpContext { int fd; }; +#ifdef __linux__ +static void tcp_log_info(int fd, const char *tag) +{ + struct tcp_info ti; + socklen_t len = sizeof(ti); + if (getsockopt(fd, IPPROTO_TCP, TCP_INFO, &ti, &len) != 0) { + return; + } + + /* 注意：tcpi_rtt 单位通常为微秒（Linux），这里转 ms 仅用于日志观察 */ + unsigned long long rtt_ms = (unsigned long long)(ti.tcpi_rtt / 1000u); + unsigned long long rttvar_ms = (unsigned long long)(ti.tcpi_rttvar / 1000u); + + logger_log("INFO", "tcpinfo", + "tag=%s state=%u retransmits=%u probes=%u backoff=%u " + "rto=%u ato=%u rtt_ms=%llu rttvar_ms=%llu " + "snd_cwnd=%u snd_ssthresh=%u snd_mss=%u rcv_mss=%u " + "lost=%u retrans=%u fackets=%u " + "last_data_sent_ms=%u last_data_recv_ms=%u", + tag ? tag : "sample", + (unsigned)ti.tcpi_state, + (unsigned)ti.tcpi_retransmits, + (unsigned)ti.tcpi_probes, + (unsigned)ti.tcpi_backoff, + (unsigned)ti.tcpi_rto, + (unsigned)ti.tcpi_ato, + rtt_ms, + rttvar_ms, + (unsigned)ti.tcpi_snd_cwnd, + (unsigned)ti.tcpi_snd_ssthresh, + (unsigned)ti.tcpi_snd_mss, + (unsigned)ti.tcpi_rcv_mss, + (unsigned)ti.tcpi_lost, + (unsigned)ti.tcpi_retrans, + (unsigned)ti.tcpi_fackets, + (unsigned)ti.tcpi_last_data_sent, + (unsigned)ti.tcpi_last_data_recv); +} +#endif + static int tcp_set_nodelay(int fd) { int flag = 1; @@ -178,6 +221,7 @@ static ssize_t tcp_send(OmniContext *c, const void *buf, size_t len) struct TcpContext *ctx = (struct TcpContext *)c; if (!ctx || ctx->fd < 0) return OMNI_ERR_PARAM; + uint64_t t0 = omni_now_ms(); MsgHeader hdr; hdr.magic = htonl(MSG_MAGIC); hdr.length = htonl((uint32_t)len); @@ -196,6 +240,13 @@ static ssize_t tcp_send(OmniContext *c, const void *buf, size_t len) return OMNI_ERR_IO; } + uint64_t t1 = omni_now_ms(); + logger_on_proto_send_latency(t1 - t0); + logger_log("DEBUG", "tcp", "send payload_bytes=%zu header_bytes=%zu proto_ms=%llu", + len, (size_t)MSG_HEADER_SIZE, (unsigned long long)(t1 - t0)); +#ifdef __linux__ + tcp_log_info(ctx->fd, "after_send"); +#endif return (ssize_t)len; } @@ -204,6 +255,7 @@ static ssize_t tcp_recv(OmniContext *c, void *buf, size_t len) struct TcpContext *ctx = (struct TcpContext *)c; if (!ctx || ctx->fd < 0) return OMNI_ERR_PARAM; + uint64_t t0 = omni_now_ms(); uint8_t header_buf[MSG_HEADER_SIZE]; ssize_t n1 = tcp_read_n(ctx->fd, header_buf, MSG_HEADER_SIZE); if (n1 <= 0) { @@ -233,6 +285,13 @@ static ssize_t tcp_recv(OmniContext *c, void *buf, size_t len) return OMNI_ERR_IO; } + uint64_t t1 = omni_now_ms(); + logger_on_proto_recv_latency(t1 - t0); + logger_log("DEBUG", "tcp", "recv payload_bytes=%u header_bytes=%zu proto_ms=%llu", + payload_len, (size_t)MSG_HEADER_SIZE, (unsigned long long)(t1 - t0)); +#ifdef __linux__ + tcp_log_info(ctx->fd, "after_recv"); +#endif return (ssize_t)payload_len; } diff --git a/tcp_impl.o b/tcp_impl.o deleted file mode 100644 index 79355db31f1bcf2cd69bb35167e9df66e86b4730..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 7912 zcmb_geQZ6t6HjV6f1maTT4>~=!1s_38ffyYgOaeFNup|yY_QS zGTgF8?e^rdA+3L;Y*c8Iwo27BZ9*fW2-0?2(*1$hmP*l z%*~BGAnZub@7~|J_k7)R&%MttTU$5P1OkF7ARZIfdyEP(e(&{mvurktda*!!wqW_? zueA}}oRt*eVmq?g>AbhE4U0B~=CpmvQPTXL$XQ1&C1?xdxas}%MW;G+CA%p;lgpUPs%$*lBH>$HPTxc z5#8%#uPD6t>;p4sobA0|ZvCO$8tf;Y9NT{lbiNmOx5Y6lW+fY)9EbYaVtrrWluS6MyICDbizq7qverlQ)=;pIPz~ThzpK| zPf-4@_s-b2uy07{4MX4T6-KdzjqD7WUYL=)PO!Qtw2a8?*-pXy29|ki7g%np#?d-w8W_R^XtNwayyK{+L>mD%bzC zsRhHQXVXHqsiGNgPcfqr#TlU)qo{8idE9#+rEXjnyy25nl}}N{ls=bZke?$H{`^nD z=`CCc7X_-> zTtxILRp%eUj8j`$wzbM|cu1e3)u-~>vxbpaBV;L1aKa;yH3l^Z3<;tltZk*wsD5~; z)+pTd?rf+4aILgP4K9ZJ;3}-7YCY(W9U^u1!`9IC;p89&-r$V9EvN6n`d9SeFk;Uh zh?i$$%)t2)xi3AUppi%CDJ0+_H4q7knHL^GfK=F;D4g!vo6ZU)v=>5))^IuYM~l`` zM5Zs-1T}r=Z1K+Ad<{|STWTzZk1AKou|Gy7%0r!(3bfGI5^|%+2a#^H{^Yq|Kimd% zCn&G>&huN!3F?%O?!dthKY)uwxpZug<3`$}iKG(`I@xS0-P8~lZY(3L9Xncgh_*y3 zK82l3=1#y^@025&bs3u_Qq1+^bkEmKi2&E z*J?J-n_2TDM)>6OG5S5|IZ)6o-U=C`gP;JJnjj|Gp>k4a&9!XClc%2BM%;RbOD#ARwS8@McqU?C6eim4wQPlM3>VA z38K?Yr*b$G;EObyOjf6oP^Jp9P)OTE4Cg~SCfc)(Bc~=s%1w7B#m5!;G8k{ya5~EvFKGDP8h%*A7i;*> zHC*@W*9vF9mSGOjy9UmF{ocUYuRm+@b-zY6oW`>KpKJI%8h%y7bvtL1fgrYXwciyB z4V>*-(!k!*##DrEpTC@2{AF zvtL~X&VKc1@^!xsX*kK?IKQLe`u=)X!}a|&tl{(*D$Ds;!*##L70!OWh&e?6G;sFo zih;9VvnjwJGjA7axV~N+6wZ42ezVoUS??|b=e&(+^7VM`({O#=|ES^j!CsEfUo~8h z&$G1HAY#*LyB_Q9^JKqU;Jm1^tY$9Tu@9jZ}`m$*an3`3CFnajAWw(LzcglVP=kJsw2F~9p0|w6D zDPsoC{z}8aV|&=&AUUMr>~FJyv%eyg>+W)+ZFsv`|J}*0EN-zO*V*feP(12JMW`*8 z6QOL{??^5+LudgF(S2Qeq%@_QnO05d4Opy=N;$M z0}5B=-k*%$?;3iUVd{Sf43atB`KvIOWKv$}^nInDzI$|H`x$!-4H{zVKQhN35%gc> zU$g%(IF;ge2VH_dyXCJC6hB%c*3a>K0vPFU#G})I(og>f=)~^u``ci0TOap{ny+Kj zHpe~(j7qi{zl&A;XZuMO(JOdJra8a1|t3;jESH{3#&u6Yy;E5ln4cje@GRDjfzbCCw|s*?z^YEdr5Gc2kyJ) z{?7NgA8B7wyB>GDT#U%YcChO!LK(|7UFZFr^|NN?WxsjX{t?iupR}=`d#%ySnw2eB zCC%!d+GAaaTI#e_g70KR%X?bagPCTj<@Una)xe&^FjvqOfV0}z=q$@FpThOk??7}0 zxwCHgoWl=SwA7ig(HS<fpq^%3SmeG~1QtRm;_7>6K6bZm5* zd0+VyJ&db!XPSXIYx}cRqeXSj&Ag|f4gpx|50GksnN3<=Es)FkCETf{{-}+2&*jw_ z?n<-15@xR!M)u!w&frFvLnue~pJU31jukwWX`>`s^m};flZ#FQvr%hTJ)}Qnr$6OL zU&{w(tzApey6A7gW+0mn%vjCd)7_J{VLf0|^9`cO-qV5Uoz|sJt6+V-*!P>+i+rFQ z(KfX3Lt!rAy}5KzI!tYvHF^b3)0}1nW+5c->NUvV8Z(!}@>-rjPnT)M!aoZO3-dV+ zX)QQu<2jG5f%Rzl>>N+9{26X6^#YC|I4iS}ZMVEF5c6-0i9yOYBgSTDSIxXK_f_yPDw0);Xv-UUU1D63RS-sd}=<0uLpO0^!y=``<%~mih zW6imhHb;8_@Zv#q9lvxD_ladv;bGkjMnkc<9`WghkxXrGjj(Ja&D6fWo<24ZOGYZh z`vP5E+?>UdG1JF&(ka8--kSBLb=?TY(%V}zHY;$}x$p5FmeG?DGgaZw(8JG1jZ~sS zU>j{zAa&z|sWvsg=H9)szHW~jRJiO>E@f;I zXOg==L@}2i6!I1LGLyW{?IQaZg}ei2k{{;gLQ*-QD-Zj1p;Cf1p|q0fc=b2pjj(h} z`n*QK?h-hyd2N8L6}U?@j@Ja({Q_^qrULO=U~Y$jeRtBs093;ttAY2{z@M#w_t(G& zYv73*_zN}g4K;Aw%W8Fv*TCPZfxip*Dpn6)n|#E;O%28p>9`WcOB=-d$Qit8oWZ-r znQ%On(OEbYkEg=o-m_qkU-=+FAv2arvUqB65biHbENbXFOX!J=Zn7aWmCV3pho>SG zi5UD<0OO1q3J(XvL&N;yirdZTHnYH<-e7NE&w-xclLvP0>QW(RzsMVp1zZRA7d-Ju zF$rHL;n;5^)L#yR^p7A2gjW!c9^uCj1S0%Sd&%AwGvRlO_4{H*|0`gSpN}OR?*!rB zO880%pOfP(Wsotj~|8l({ z310<%DW8Od%YAr5!sR}klyJEZ=OtY3!=D1Dx;F8u7;8cRh;VvSS37X3cbx-|+UD#b zfjjrNL&EO>U8?sJ2}j?AUyyKlU%nJLPIwN7VIY0uz$wq~9XRdFF9LVwnG^3S;`p0H z`5cvSIiGiG;3ox6c^<(efhHU{<$1<|Q=Uc1zkGh`F+m`l zV;;!1s{jY6f^Tx1DdAKip(nv6nKE?+{#Mz@ zUtO^tOlFm|kxJ`^IRd^gf<6?C8li+PGW>s&56rQ**ME6ze|~#nPl$aKORh^i&TC+x ziXVndOYxBh@(Fu)RyMuqh)X#7km*5KpwHX2$G=zTY{`C4i1_cx zAn=qw!8?FKduMz<|9=|lCq*$k*N*^Rt$*vWVL<)-%NQ%v~fkS9CBp97`=hJ4phcDzRYlt1bq9f5&9o%R#L{sbyX