Created
May 29, 2018 07:41
-
-
Save cloudwu/7c59d768d1e68f2797c4772b3ea96437 to your computer and use it in GitHub Desktop.
Revisions
-
cloudwu created this gist
May 29, 2018 .There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode charactersOriginal file line number Diff line number Diff line change @@ -0,0 +1,81 @@ net=5.422477ms,cluster=91.399046ms,cpu=323.263431ms,latency=5.447901ms,time=425.532855ms login1:00000063 122.286771ms trace gm login1:00000063 102.904420ms(net=3.207950ms,cluster=0.250590ms,cpu=3.580064ms,time=7.038604ms) call : @./service/agent/player/war_base.lua:363 @./service/agent/player/war_base.lua:130 @./service/agent/agent_lock.lua:62 login1:00000009 3.568610ms request login1:00000009 3.458540ms(time=0.250590ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center:0000005d 0.250590ms tracecall begin center:00000056 0.069562ms request center:00000056 response center:0000005d tracecall end login1:00000009 0.011454ms resume login1:00000009 response login1:00000063 98.974590ms resume login1:00000063 98.501905ms(net=2.214527ms,cluster=91.148456ms,cpu=95.556837ms,time=188.919820ms) call : @./service/agent/player/war_base.lua:373 @./service/agent/player/war_base.lua:130 @./service/agent/agent_lock.lua:62 login1:00000009 95.494818ms request login1:00000009 93.362983ms(time=91.148456ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center:0000005d 91.148456ms tracecall begin center:00000056 90.935021ms request center:00000056 90.467923ms(net=0.356191ms,cluster=7.154820ms,cpu=15.830784ms,time=16.220777ms) call : @./service/scene_mgr/scene_mgr_base.lua:1215 @./service/scene_mgr/scene_mgr_base.lua:1054 @./lualib/lock.lua:47 center:00000055 8.102985ms request center:00000055 8.050744ms(net=0.356191ms,cluster=7.154820ms,cpu=7.660751ms,time=15.171762ms) call : @./lualib/utils.lua:202 @./service/cluster_room_mgr/logic.lua:163 @./lualib/utils.lua:392 center:00000009 7.653487ms request center:00000009 7.511011ms(time=7.154820ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1:00000062 7.154820ms tracecall begin login1:0000001e 6.972115ms request login1:0000001e 6.854223ms(cpu=0.144991ms,time=0.144991ms) call : @./service/node_room_mgr/logic.lua:152 @./service/node_room_mgr/logic.lua:121 @./lualib/lock.lua:47 login1:00000003 0.144991ms request login1:00000003 end login1:0000001e 0.104762ms resume login1:0000001e response login1:00000062 tracecall end center:00000009 0.007264ms resume center:00000009 response center:00000055 0.067048ms resume center:00000055 response center:00000056 82.109318ms resume center:00000056 82.070487ms(net=0.593092ms,cluster=72.492454ms,cpu=73.227185ms,time=146.312731ms) call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:1248 @./service/scene_mgr/scene_mgr_base.lua:1054 center:00000009 73.206232ms request center:00000009 73.085546ms(time=72.492454ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1:00000062 72.492454ms tracecall begin login1:0000006b 71.896848ms request login1:0000006b response login1:00000062 tracecall end center:00000009 0.020953ms resume center:00000009 response center:00000056 8.356369ms resume center:00000056 8.269766ms(net=0.689753ms,cluster=5.333918ms,cpu=6.723759ms,time=12.747430ms) call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:788 @./service/scene_mgr/scene_mgr_base.lua:1069 center:00000009 6.715099ms request center:00000009 6.023671ms(time=5.333918ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login2:00000062 5.333918ms tracecall begin login2:00000068 4.888890ms request login2:00000068 1.995785ms(net=0.520179ms,cluster=0.239415ms,cpu=1.093714ms,time=1.853308ms) call : @./lualib/utils.lua:202 @./service/scene/scene_base.lua:475 @./lualib/utils.lua:392 login2:00000009 1.086730ms request login2:00000009 0.759594ms(time=0.239415ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1:0000006a 0.239415ms tracecall begin login1:0000001d 0.058108ms request login1:0000001d response login1:0000006a tracecall end login2:00000009 0.006984ms resume login2:00000009 response login2:00000068 0.054197ms resume login2:00000068 response login2:00000062 tracecall end center:00000009 0.008660ms resume center:00000009 response center:00000056 1.395149ms resume center:00000056 1.318603ms(net=0.565434ms,cluster=0.609296ms,cpu=1.177523ms,time=2.352253ms) call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:1094 @./service/scene_mgr/scene_mgr_base.lua:1073 center:00000009 1.174730ms request center:00000009 1.174730ms(time=0.609296ms) sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1:00000062 0.609296ms tracecall begin login1:0000006b 0.307023ms request login1:0000006b response login1:00000062 tracecall end center:00000009 0.002793ms resume center:00000009 response center:00000056 0.053079ms resume center:00000056 response center:0000005d tracecall end login1:00000009 0.062019ms resume login1:00000009 response login1:00000063 2.865169ms resume login1:00000063 response This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode charactersOriginal file line number Diff line number Diff line change @@ -0,0 +1,110 @@ login1.log:[2018-05-29 09:38:11.98 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229462446872 trace gm login1.log:[2018-05-29 09:38:11.99 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229481829223 call : @./service/agent/player/war_base.lua:363 @./service/agent/player/war_base.lua:130 @./service/agent/agent_lock.lua:62 login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229482059700 request login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229482087916 session (Ubuntu1626488-s1_center-46):00000063-7 login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229482091547 cluster s1_center login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229482169770 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229485616856 resume login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229485628310 response login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229485634456 end login1.log:[2018-05-29 09:38:11.99 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229485759053 resume login1.log:[2018-05-29 09:38:11.99 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229486231738 call : @./service/agent/player/war_base.lua:373 @./service/agent/player/war_base.lua:130 @./service/agent/agent_lock.lua:62 login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229486333707 request login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229486358570 session (Ubuntu1626488-s1_center-47):00000063-7 login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229486377288 cluster s1_center login1.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229488465542 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login1.log:[2018-05-29 09:38:11.99 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229490029986 tracecall begin login1.log:[2018-05-29 09:38:11.99 INF] [0000001e *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229490119663 request login1.log:[2018-05-29 09:38:11.99 INF] [0000001e *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229490237555 call : @./service/node_room_mgr/logic.lua:152 @./service/node_room_mgr/logic.lua:121 @./lualib/lock.lua:47 login1.log:[2018-05-29 09:38:11.99 INF] [00000003 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229490322202 request login1.log:[2018-05-29 09:38:11.99 INF] [00000003 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229490467193 end login1.log:[2018-05-29 09:38:11.99 INF] [0000001e *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229496987016 resume login1.log:[2018-05-29 09:38:11.99 INF] [0000001e *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497091778 response login1.log:[2018-05-29 09:38:11.99 INF] [0000001e *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497099041 end login1.log:[2018-05-29 09:38:12.02 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497184806 tracecall end login1.log:[2018-05-29 09:38:12.02 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229498405073 tracecall begin login1.log:[2018-05-29 09:38:12.02 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229498626330 request login1.log:[2018-05-29 09:38:12.09 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229570523178 response login1.log:[2018-05-29 09:38:12.09 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229570531559 end login1.log:[2018-05-29 09:38:12.09 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229570897527 tracecall end login1.log:[2018-05-29 09:38:12.09 INF] [0000006a *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229576866163 tracecall begin login1.log:[2018-05-29 09:38:12.09 INF] [0000001d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577028194 request login1.log:[2018-05-29 09:38:12.09 INF] [0000001d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577086302 response login1.log:[2018-05-29 09:38:12.09 INF] [0000001d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577095521 end login1.log:[2018-05-29 09:38:12.09 INF] [0000006a *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577105578 tracecall end login1.log:[2018-05-29 09:38:12.09 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578912791 tracecall begin login1.log:[2018-05-29 09:38:12.09 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578976207 request login1.log:[2018-05-29 09:38:12.09 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579283230 response login1.log:[2018-05-29 09:38:12.09 INF] [0000006b *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579289376 end login1.log:[2018-05-29 09:38:12.09 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579522087 tracecall end login1.log:[2018-05-29 09:38:12.10 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229581766506 resume login1.log:[2018-05-29 09:38:12.10 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229581828525 response login1.log:[2018-05-29 09:38:12.10 INF] [00000009 *skynet*] :[] <TRACE :00000063-7> 412229581838023 end login1.log:[2018-05-29 09:38:12.10 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229581868474 resume login1.log:[2018-05-29 09:38:12.10 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229584733643 response login1.log:[2018-05-29 09:38:12.10 INF] [00000063 *skynet*] :[] <TRACE :00000063-7> 412229584740906 end center.log:[2018-05-29 09:38:11.99 INF] [0000005d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229483691192 tracecall begin center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229483800144 request center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229483869706 response center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229483886189 end center.log:[2018-05-29 09:38:11.99 INF] [0000005d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-46):00000063-7> 412229483941782 tracecall end center.log:[2018-05-29 09:38:11.99 INF] [0000005d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229488745466 tracecall begin center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229488851345 request center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489318443 call : @./service/scene_mgr/scene_mgr_base.lua:1215 @./service/scene_mgr/scene_mgr_base.lua:1054 @./lualib/lock.lua:47 center.log:[2018-05-29 09:38:11.99 INF] [00000055 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489510647 request center.log:[2018-05-29 09:38:11.99 INF] [00000055 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489562888 call : @./lualib/utils.lua:202 @./service/cluster_room_mgr/logic.lua:163 @./lualib/utils.lua:392 center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489650050 request center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489738888 cluster s1_login1 center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229489792526 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497296273 resume center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497303537 response center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497309683 end center.log:[2018-05-29 09:38:11.99 INF] [00000055 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497546584 resume center.log:[2018-05-29 09:38:11.99 INF] [00000055 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497613632 response center.log:[2018-05-29 09:38:11.99 INF] [00000055 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497629835 end center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497677048 resume center.log:[2018-05-29 09:38:11.99 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497715879 call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:1248 @./service/scene_mgr/scene_mgr_base.lua:1054 center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497843549 request center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497921213 cluster s1_login1 center.log:[2018-05-29 09:38:11.99 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229497964235 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571028828 resume center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571049781 response center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571056486 end center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571429997 resume center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571516600 call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:788 @./service/scene_mgr/scene_mgr_base.lua:1069 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571605997 request center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229571619686 cluster s1_login2 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229572297425 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578312436 resume center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578321096 response center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578326963 end center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578391217 resume center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578467763 call : @./lualib/utils.lua:202 @./service/scene_mgr/scene_mgr_base.lua:1094 @./service/scene_mgr/scene_mgr_base.lua:1073 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578468042 request center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578468042 cluster s1_login1 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578468042 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579639979 resume center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579642772 response center.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579683001 end center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579733287 resume center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579786366 response center.log:[2018-05-29 09:38:12.08 INF] [0000005d *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229579893922 tracecall end center.log:[2018-05-29 09:38:12.08 INF] [00000056 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229580292017 end login2.log:[2018-05-29 09:38:12.08 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229572726810 tracecall begin login2.log:[2018-05-29 09:38:12.08 INF] [00000068 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229572831292 request login2.log:[2018-05-29 09:38:12.08 INF] [00000068 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229575724397 call : @./lualib/utils.lua:202 @./service/scene/scene_base.lua:475 @./lualib/utils.lua:392 login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229576319166 request login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229576353807 cluster s1_login1 login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229576646302 sleep : @./skynet/lualib/skynet/socketchannel.lua:374 @./skynet/service/clusterd.lua:147 @./skynet/service/clusterd.lua:252 login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577398912 resume login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577405896 response login2.log:[2018-05-29 09:38:12.08 INF] [00000009 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577410925 end login2.log:[2018-05-29 09:38:12.08 INF] [00000068 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577665985 resume login2.log:[2018-05-29 09:38:12.08 INF] [00000068 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577720182 response login2.log:[2018-05-29 09:38:12.08 INF] [00000068 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229577738340 end login2.log:[2018-05-29 09:38:12.08 INF] [00000062 *skynet*] :[] <TRACE (Ubuntu1626488-s1_center-47):00000063-7> 412229578060728 tracecall end This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode charactersOriginal file line number Diff line number Diff line change @@ -0,0 +1,263 @@ local function read_logs(filename) local function filterlog(logline) return string.match(logline, "(.-)%..-%[.-%] %[(%w+).-<TRACE (.-)> (%d+) (%w+) *(.*)") end local logs = {} local sessions = {} local cluster = {} for line in io.lines(filename) do local node, addr, tag, timestamp, what, info = filterlog(line) if tag then -- 特别处理 session / cluster / sleep 组合 -- 如果遇到 cluster , 那么下一条 sleep 和该条 cluster 绑定。 -- 如果 cluster 的 tag 和 sleep 的 tag 不同，那么找到最近的 session 绑定。 local log = logs[node] if log == nil then log = {} logs[node] = log end table.insert(log, { tag = tag, timestamp = math.tointeger(timestamp), address = addr, what = what, info = info, node = node, }) end end return logs end local function filter_log(logs, node, tag) local result = {} local subtag local cluster local sessions = {} for _, item in ipairs(logs[node]) do if item.tag == tag then local what = item.what if what == "session" then subtag = item.info elseif what == "cluster" then cluster = item.info else if what == "sleep" then item.session = { subtag = subtag or tag, node = cluster } if subtag ~= tag then table.insert(sessions, subtag) end subtag = nil cluster = nil end table.insert(result, item) end else if item.tag == subtag and item.what == "cluster" then cluster = item.info end end end return result, sessions end -- 按 tracecall begin/end 分组 local function filter_group(list) local groups = {} local stack = {} for _, item in ipairs(list) do if item.what == "tracecall" then if item.info == "begin" then local newframe = { item } table.insert(groups, newframe) table.insert(stack, newframe) elseif item.info == "end" then local frame = stack[#stack] if frame then table.insert(frame, item) table.remove(stack) -- pop stack end end else local frame = stack[#stack] if frame then table.insert(frame, item) end end end return groups end local function filter_log_all(logs, node, tag) local result, sessions = filter_log(logs, node, tag) local subs = {} for _, subtag in ipairs(sessions) do for nodename in pairs(logs) do subs[nodename .. "/" .. subtag] = filter_group(filter_log(logs, nodename, subtag)) end end return result, subs end -- 从 logs 中产生调用树，可能会用到 subs 中的子 session local function gen_tree(logs, subs) local result = {} local stack = { { frame = result, address = nil , open = true }, } for _, item in ipairs(logs) do local top while true do top = stack[#stack] if item.address ~= top.address then if top.open then local sublist = {} table.insert(top.frame, sublist) table.insert(stack, { frame = sublist, address = item.address, open = true }) else table.remove(stack) end else break end end if top.open then table.insert(top.frame, item) if item.what == "response" or item.what == "error" or item.what == "end" then -- 当用 skynet.response 回应时，就不会用 response , 但是会 end 。此时，cpu 开销不计算在内，时间开销计算在外部延迟中。 top.open = false elseif item.what == "sleep" and item.session then -- sub session local nodename = item.session.node nodename = nodename:match "s1_(.*)" -- todo: 为 s1_ 专门写的 local tagname = nodename .. "/" .. item.session.subtag local sublist = subs[tagname] if sublist and sublist[1] then local list = table.remove(sublist, 1) table.insert(top.frame, gen_tree(list, subs)) end end end end return result[1] end local function calc_time(tree) local ti = { time = 0, cpu = 0, latency = 0, net = 0, sleep = 0, cluster = 0, } for i, item in ipairs(tree) do if item.address then local next_time for j = i+1, #tree do local next_item = tree[j] if #next_item == 0 then next_time = next_item.timestamp end end if next_time then item.time = next_time - item.timestamp ti.time = ti.time + item.time local subframe = tree[i+1] if subframe.address == nil then local subti = calc_time(subframe) if item.what == "call" then local latency = item.time - subti.time ti.latency = ti.latency + latency ti.cpu = ti.cpu + subti.cpu ti.latency = ti.latency + subti.latency ti.net = ti.net + subti.net ti.sleep = ti.sleep + subti.sleep ti.cluster = ti.cluster + subti.cluster item.detail = subti elseif item.what == "sleep" then local net = item.time - subti.time ti.net = ti.net + net ti.cluster = ti.cluster + subti.time item.detail = subti end else -- todo : 把自己调用自己的时间统计分离为 cpu 消耗和调度消耗 -- 目前，自己调用自己会把当前服务响应其它无关请求需要的时间计入 cpu if item.what == "sleep" then ti.sleep = ti.sleep + item.time else ti.cpu = ti.cpu + item.time end end end end end return ti end ------------------------------ local function print_item(item) print(item.tag, item.address, item.what, item.info) end local function print_groups(groups) for idx, group in ipairs(groups) do print("frame", idx) for _, item in ipairs(group) do print_item(item) end end end local function time_detail(ti) local result = {} for k,v in pairs(ti) do if v > 0 then table.insert(result, string.format("%s=%fms",k, v/1000000)) end end return table.concat(result, ",") end local function timestring(node) if node.time == nil then return "" elseif node.detail then return string.format("%fms(%s)", node.time / 1000000, time_detail(node.detail) ) else return string.format("%fms", node.time / 1000000) end end local function print_tree(tree, level) if not tree.address then for _, subtree in ipairs(tree) do print_tree(subtree, level + 1) end else print(string.format("%s%s:%s %s %s %s", string.rep(" ", level-1), tree.node,tree.address, timestring(tree), tree.what, tree.info)) end end local function main() local logs = assert(read_logs "trace.log") local log, sub = filter_log_all(logs, "login1", ":00000063-7") local tree = gen_tree(log, sub) local ti = calc_time(tree) print(time_detail(ti)) print_tree(tree, 0) end main()