Created
May 29, 2018 07:41
-
-
Save cloudwu/7c59d768d1e68f2797c4772b3ea96437 to your computer and use it in GitHub Desktop.
tracelog
This file contains 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 characters
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 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 characters
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 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 characters
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() |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment