Skip to content

Instantly share code, notes, and snippets.

@cloudwu

cloudwu/report.txt

Created May 29, 2018 07:41
Show Gist options
  • Star 5 You must be signed in to star a gist
  • Fork 2 You must be signed in to fork a gist
  • Save cloudwu/7c59d768d1e68f2797c4772b3ea96437 to your computer and use it in GitHub Desktop.
Save cloudwu/7c59d768d1e68f2797c4772b3ea96437 to your computer and use it in GitHub Desktop.
Download ZIP
tracelog
Raw
report.txt
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
Raw
trace.log
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
Raw
tracelog.lua
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