Dtrace on Warzone
Dtrace on Warzone
Learning to use Dtrace, thought it would be bit more interesting to do on this application. Creating this for tracking own progress, and if anything I find can be of assistance to developers\programmers.
From my understanding Dtrace is the most effective way to gain insight into what applications request of the system and although other tools exist such as Systemtap if a mistake is made can cause the kernel to crash, and most tools which monitor applications simply through monitoring them impact the process.
Dtrace will be safe to use vs other tools as per posts like https://blogs.oracle.com/bmc/entry/dtrace_safety
Relateable link to the PID provider http://dtrace.org/blogs/brendan/2011/02 ... -provider/
Comparison http://www.sourceware.org/systemtap/wik ... Comparison
For each of these my settings are : 1920 x 1080 resolution
Texture size : 2048
Vsync = on
FSAA = 8*
Shaders = on
Quite new to this so if any statements are wrong or appears ignorant I'll modify posts. Let's see how far this goes..
From my understanding Dtrace is the most effective way to gain insight into what applications request of the system and although other tools exist such as Systemtap if a mistake is made can cause the kernel to crash, and most tools which monitor applications simply through monitoring them impact the process.
Dtrace will be safe to use vs other tools as per posts like https://blogs.oracle.com/bmc/entry/dtrace_safety
Relateable link to the PID provider http://dtrace.org/blogs/brendan/2011/02 ... -provider/
Comparison http://www.sourceware.org/systemtap/wik ... Comparison
For each of these my settings are : 1920 x 1080 resolution
Texture size : 2048
Vsync = on
FSAA = 8*
Shaders = on
Quite new to this so if any statements are wrong or appears ignorant I'll modify posts. Let's see how far this goes..
Last edited by Tzeentch on 23 Jan 2015, 14:21, edited 1 time in total.
Re: Dtrace on Warzone
Warzone memory requested sizes (bytes) from malloc, printed out into a Distribution graph using ASCI format.
Warzone memory returned (bytes) from requested
Tracing warzone memory reqests for bytes size 16384, traced during game 1v1 against medium Nexus AI. Only seen once near start and couldn't replicate
Then checked a bit more common 256 size memory requests.
Checked all realted malloc data later on... Curious about value 34359738368
game crashed during trace of 34359738368 due to using PID provider which isn't stable due to exposing application functions perhaps.
due to pointer is to an address in user-land, whereas DTrace runs in kernel-land – so it can’t be dereferenced directly..
oops, need instead... seems to crash game
On FreeBSD so checking network function, (whilst in online lobby) join game list, host game and refresh server list.
first checked for getaddrinfo function:name
59594 pid57814 libc.so.7 getaddrinfo entry
59595 pid57814 libc.so.7 getaddrinfo return
something went wrong there.
Code: Select all
# dtrace -n 'pid$target::malloc:entry { @ = quantize(arg0); }' -p 57036
dtrace: description 'pid$target::malloc:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
2 | 0
4 |@@@@ 3642
8 |@ 704
16 |@ 982
32 |@@@@@@@@@@@@@@@@ 15336
64 |@@@@@@@@@@@@@@@@ 15009
128 |@ 1367
256 |@@ 1505
512 | 8
1024 | 51
2048 | 41
4096 | 20
8192 | 0
16384 | 55
32768 | 0
Code: Select all
dtrace -n 'pid$target::malloc:return { @ = quantize(arg0); }' -p 57036
dtrace: description 'pid$target::malloc:return ' matched 1 probe
^C
value ------------- Distribution ------------- count
2048 | 0
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 63469
8192 | 0
Code: Select all
# dtrace -n 'pid$target::malloc:entry /arg0 == 16384/ { ustack(); }' -p 57036
dtrace: description 'pid$target::malloc:entry ' matched 1 probe
CPU ID FUNCTION:NAME
3 59594 __malloc:entry
libc.so.7`__malloc+0x1
libogg.so.8`ogg_stream_init+0x4c
libvorbisfile.so.6`_ov_open1+0x106
libvorbisfile.so.6`ov_open_callbacks+0x22
warzone2100`sound_CreateOggVorbisDecoder(PHYSFS_File*, bool)+0xc1
warzone2100`sound_PlayStreamWithBuf(PHYSFS_File*, float, void(*)(void*), void*, unsigned long, unsigned int)+0xf4
warzone2100`0x604a51
warzone2100`0x604c23
warzone2100`0x606812
warzone2100`0x60541c
warzone2100`sound_Update(void)+0x37
warzone2100`audio_Update(void)+0x235
warzone2100`gameLoop(void)+0xae1
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
Then checked a bit more common 256 size memory requests.
Code: Select all
dtrace -n 'pid$target::malloc:entry /arg0 == 256/ { ustack(); }' -p 57036
dtrace: description 'pid$target::malloc:entry ' matched 1 probe
CPU ID FUNCTION:NAME
1 59594 __malloc:entry
libc.so.7`__malloc+0x1
libc++.so.1`operator new(unsigned long)+0x2a
warzone2100`std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> >::vector(std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> > const&)+0x3c
warzone2100`proj_UpdateAll(void)+0x1d
warzone2100`gameLoop(void)+0x8ae
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
2 59594 __malloc:entry
libc.so.7`__malloc+0x1
libc++.so.1`operator new(unsigned long)+0x2a
warzone2100`std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> >::vector(std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> > const&)+0x3c
warzone2100`proj_UpdateAll(void)+0x1d
warzone2100`gameLoop(void)+0x8ae
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
3 59594 __malloc:entry
libc.so.7`__malloc+0x1
libc++.so.1`operator new(unsigned long)+0x2a
warzone2100`std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> >::vector(std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> > const&)+0x3c
warzone2100`proj_UpdateAll(void)+0x1d
warzone2100`gameLoop(void)+0x8ae
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
3 59594 __malloc:entry
libc.so.7`__malloc+0x1
libc++.so.1`operator new(unsigned long)+0x2a
warzone2100`std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> >::vector(std::__1::vector<PROJECTILE*, std::__1::allocator<PROJECTILE*> > const&)+0x3c
warzone2100`proj_UpdateAll(void)+0x1d
warzone2100`gameLoop(void)+0x8ae
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
Code: Select all
# dtrace -n 'pid$target::malloc: { @ = quantize(arg0); }' -p 57778
dtrace: description 'pid$target::malloc: ' matched 1190 probes
^C
value ------------- Distribution ------------- count
1 | 0
2 | 5184
4 |@@ 232419
8 | 7729
16 | 9461
32 |@@@@@@@@@@@@@@@@@@ 1660018
64 |@@@@@@@@@@@@@@@@@@ 1715728
128 |@ 99440
256 | 7851
512 | 4334
1024 | 108
2048 | 360
4096 | 36166
8192 | 0
16384 | 4382
32768 | 0
65536 | 0
131072 | 0
262144 | 0
524288 | 0
1048576 | 0
2097152 | 0
4194304 | 0
8388608 | 0
16777216 | 0
33554432 | 0
67108864 | 0
134217728 | 0
268435456 | 0
536870912 | 0
1073741824 | 0
2147483648 | 0
4294967296 | 0
8589934592 | 0
17179869184 | 0
34359738368 | 3435
68719476736 | 0
due to pointer is to an address in user-land, whereas DTrace runs in kernel-land – so it can’t be dereferenced directly..
Code: Select all
# dtrace -n 'pid$target:libc.so.7:strcmp:entry { trace(stringof(arg0)); }' -p 57036
"dtrace: error on enabled probe ID 1 (ID 62753: pid57036:libc.so.7:strcmp:entry): invalid address (0x80ac84112) in action #1"
Code: Select all
# dtrace -n 'pid$target:libc.so.7:strcmp:entry { trace(copyinstr(arg0)); }' -p 57752
first checked for getaddrinfo function:name
59594 pid57814 libc.so.7 getaddrinfo entry
59595 pid57814 libc.so.7 getaddrinfo return
Code: Select all
# dtrace -n 'pid$target::getaddrinfo:entry { printf("%s %s", copyinstr(arg1), copyinstr(arg1)); }' -p 57814
dtrace: description 'pid$target::getaddrinfo:entry ' matched 1 probe
CPU ID FUNCTION:NAME
2 59594 getaddrinfo:entry 9990 9990
2 59594 getaddrinfo:entry 53 53
2 59594 getaddrinfo:entry 9990 9990
3 59594 getaddrinfo:entry 1900 1900
2 59594 getaddrinfo:entry 8000 8000
0 59594 getaddrinfo:entry 8000 8000
3 59594 getaddrinfo:entry 8000 8000
2 59594 getaddrinfo:entry 9990 9990
Code: Select all
# dtrace -n 'pid$target::getaddrinfo:return { printf("%s %s", copyinstr(arg1), copyinstr(arg1)); }' -p 57814
dtrace: description 'pid$target::getaddrinfo:return ' matched 1 probe
dtrace: error on enabled probe ID 1 (ID 59595: pid57814:libc.so.7:getaddrinfo:return): invalid address (0x0) in action #1 at DIF offset 12
dtrace: error on enabled probe ID 1 (ID 59595: pid57814:libc.so.7:getaddrinfo:return): invalid address (0x0) in action #1 at DIF offset 12
Code: Select all
# dtrace -n 'pid$target::getaddrinfo:entry { printf("%s %s", arg0 != NULL ? copyinstr(arg0) : "<NULL>", arg1 != NULL ? copyinstr(arg1) : "<NULL>"); }' -p 57814
dtrace: description 'pid$target::getaddrinfo:entry ' matched 1 probe
CPU ID FUNCTION:NAME
0 59594 getaddrinfo:entry lobby.wz2100.net 9990
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
3 59594 getaddrinfo:entry 239.255.255.250 1900
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
1 59594 getaddrinfo:entry 192.168.1.254 8000
2 59594 getaddrinfo:entry 192.168.1.254 8000
3 59594 getaddrinfo:entry 192.168.1.254 8000
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
2 59594 getaddrinfo:entry lobby.wz2100.net 9990
Re: Dtrace on Warzone
Based on what I've read on this forum post viewtopic.php?f=32&t=11978&start=15 next task to review memset reported as an issue to do with vsync enabled. More precise details required without hindering application\adding overhead.
Re: Dtrace on Warzone
From casting my eyes on this memset is a bit further up and some other interesting info uncovered. Note this drastically slowed application, on stopping process crashed.
Taken during 4 player ffa, 3 Nexus AI's on medium. Did few basic tasks in game.
Output to log file... see attached. Checking all probes against Warzone:
This is called more than anything else, perhaps as lot of uncovered fog around.
Then memset we're going to check
Quite long so output to another file, bottom looked most interesting
Taken during 4 player ffa, 3 Nexus AI's on medium. Did few basic tasks in game.
Code: Select all
# dtrace -n 'pid$target:::entry { @[probefunc] = count(); }' -p 58558
# dtrace: description 'pid$target:::entry ' matched 39978 probes
This is called more than anything else, perhaps as lot of uncovered fog around.
Code: Select all
# dtrace -n 'pid$target::_Z16pie_GetFogStatusv:entry { @[ustack()] = count(); }' -p 58558
dtrace: description 'pid$target::_Z16pie_GetFogStatusv:entry ' matched 1 probe
^C
warzone2100`pie_GetFogStatus(void)+0x1
warzone2100`drawWater(void)+0x41a
warzone2100`draw3DScene(void)+0x744
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
1919
warzone2100`pie_GetFogStatus(void)+0x1
warzone2100`drawWater(void)+0x124
warzone2100`draw3DScene(void)+0x744
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
1919
warzone2100`pie_GetFogStatus(void)+0x1
warzone2100`drawTerrain(void)+0xa69
warzone2100`draw3DScene(void)+0x4e7
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
1919
warzone2100`pie_GetFogStatus(void)+0x1
warzone2100`drawTerrain(void)+0x93a
warzone2100`draw3DScene(void)+0x4e7
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
1919
warzone2100`pie_GetFogStatus(void)+0x1
warzone2100`drawTerrain(void)+0x18c
warzone2100`draw3DScene(void)+0x4e7
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
3250176
Code: Select all
dtrace -n 'pid$target::memset:entry { @[ustack()] = count(); }' -p 58558
Last edited by Tzeentch on 06 Feb 2015, 02:22, edited 1 time in total.
Re: Dtrace on Warzone
When checking the sync issues using Dtrace.. further work in progress
# dtrace -n 'pid$target::*setPower*:entry { @[ustack()] = count(); }' -p 4680
dtrace: description 'pid$target::*setPower*:entry ' matched 1 probe
^C
warzone2100`setPower(unsigned int, int)+0x1
warzone2100`0x58bc87
libQtScript.so.4.8.6`0x803715005
libQtScript.so.4.8.6`0x80366749d
libQtScript.so.4.8.6`0x803648f2d
libQtScript.so.4.8.6`0x80364d765
libQtScript.so.4.8.6`0x803686c0e
libQtScript.so.4.8.6`0x80366757e
libQtScript.so.4.8.6`QScriptValue::call(QScriptValue const&, QList<QScriptValue> const&)+0x312
warzone2100`0x562d49
warzone2100`triggerEvent(SCRIPT_TRIGGER_TYPE)+0xab
warzone2100`stageThreeInitialise(void)+0x1da
warzone2100`levLoadData(char const*, Sha256 const*, char*, GAME_TYPE)+0xedc
warzone2100`0x51a481
warzone2100`mainLoop(void)+0xf6
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
6
# dtrace -n 'pid$target::*setPower*:entry { @[ustack()] = count(); }' -p 4680
dtrace: description 'pid$target::*setPower*:entry ' matched 1 probe
^C
warzone2100`setPower(unsigned int, int)+0x1
warzone2100`0x58bc87
libQtScript.so.4.8.6`0x803715005
libQtScript.so.4.8.6`0x80366749d
libQtScript.so.4.8.6`0x803648f2d
libQtScript.so.4.8.6`0x80364d765
libQtScript.so.4.8.6`0x803686c0e
libQtScript.so.4.8.6`0x80366757e
libQtScript.so.4.8.6`QScriptValue::call(QScriptValue const&, QList<QScriptValue> const&)+0x312
warzone2100`0x562d49
warzone2100`triggerEvent(SCRIPT_TRIGGER_TYPE)+0xab
warzone2100`stageThreeInitialise(void)+0x1da
warzone2100`levLoadData(char const*, Sha256 const*, char*, GAME_TYPE)+0xedc
warzone2100`0x51a481
warzone2100`mainLoop(void)+0xf6
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
6
Re: Dtrace on Warzone
What you'd like to monitor is the number of bytes being set, similar to what you did to malloc(), but here it's even more useful, as memset() is essentially linear.Quite long so output to another file, bottom looked most interesting
Come on, for investigating a bug that happens once in a known program point, gdb is more than enough. Most of the backtracing stuff was already discussed in the ticket.When checking the sync issues using Dtrace..
Maps | Tower Defense | NullBot AI | More NullBot AI | Scavs | More Scavs | Tilesets | Walkthrough | JSCam
Re: Dtrace on Warzone
glcore looks to be part of memset operations (when observing Noq's screenshot download/file.php?id=15516&mode=view )
I notice on mine
libc.so.7 is being used for memset but Noq's looks like libc-2.20.so
anyhow, Using dtrace script for userlevel profiling tool (sample on-CPU user-level functions and libraries.) This was all done in the tutorial with very little going on ingame.
# /usr/share/dtrace/toolkit/hotuser -p 3228
Sampling... Hit Ctrl-C to end.
see attached file output - main functions the game is running are these 4:
Had a test only disabling Vsync, then again after re-enabling
Disabled :
Re-enabled :
I moved around in the map more on the Vsync tests, the CPU usage of these functions are both heavily dependent on how much your moving around the map actively. I've got a high end system so perhaps it's harder to detect impact vs lower end hardware that said warzone CPU usage goes from 8%-40% regardless of Vsync, but do have highest settings enabled
Then checking bytes set:
Because 64 seems most common, get stack trace of this, commonly shows same repeated entries as follows
Used Custom script so that when bytes == 64 start with shallow stack traces and increase the depth only when necessary script attached for reference. -
Then check 1 memset, second most common
Modified Custom script so that when bytes == 1 start with shallow stack traces and increase the depth only when necessary
^C
I notice on mine
libc.so.7 is being used for memset but Noq's looks like libc-2.20.so
anyhow, Using dtrace script for userlevel profiling tool (sample on-CPU user-level functions and libraries.) This was all done in the tutorial with very little going on ingame.
# /usr/share/dtrace/toolkit/hotuser -p 3228
Sampling... Hit Ctrl-C to end.
see attached file output - main functions the game is running are these 4:
Code: Select all
libc.so.7`memcpy 147 1.1%
libc.so.7`strcmp 185 1.4%
warzone2100`atmosDrawParticles(void) 212 1.6%
warzone2100`atmosUpdateSystem(void) 253 1.9%
Disabled :
Code: Select all
warzone2100`drawRadar(void) 181 0.9%
libnvidia-glcore.so.1`0x80712db2b 189 1.0%
warzone2100`avUpdateTiles(void) 210 1.1%
libc.so.7`memcpy 213 1.1%
warzone2100`_ZNSt3__16__sortIRPFbRK4EDGES3_EPS1_EEvT0_S8_T_ 216 1.1%
warzone2100`__glcCharMapGetGlyph 295 1.5%
warzone2100`_ZNSt3__118__insertion_sort_3IRPFbRK4EDGES3_EPS1_EEvT0_S8_T_ 329 1.7%
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels 336 1.7%
libc.so.7`strlen 341 1.8%
warzone2100`draw3DScene(void) 724 3.8%
Code: Select all
warzone2100`pie_SetFogStatus(bool) 12 0.5%
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels 13 0.5%
libc.so.7`strlen 17 0.6%
libc.so.7`strcmp 20 0.8%
warzone2100`__glcCharMapGetGlyph 20 0.8%
libc.so.7`memcpy 33 1.3%
warzone2100`draw3DScene(void) 36 1.4%
warzone2100`atmosDrawParticles(void) 69 2.6%
warzone2100`atmosUpdateSystem(void) 105 4.0%
Then checking bytes set:
Code: Select all
# dtrace -n 'pid$target::memset:entry { @ = quantize(arg2); }' -p 3228
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@ 31840
2 |@@@@@@ 27353
4 |@@@@ 18915
8 |@ 4175
16 |@ 3307
32 |@@ 7280
64 |@@@@@@@@@@@@ 51411
128 |@@ 8623
256 |@@@ 13149
512 | 16
1024 |@@ 7563
2048 | 4
4096 |@ 3756
8192 | 1040
16384 | 115
32768 | 0
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg0 == 64/ { ustack(); }' -p 3228
^C
1 59411 memset:entry
libc.so.7`memset+0x1
libc.so.7`__calloc+0xf52
libpulse.so.0.12.4`pa_xmalloc0+0x25
libpulse.so.0.12.4`0x80f41ea26
libpulsecommon-0.9.23.so`pa_pdispatch_register_reply+0xc7
libpulse.so.0.12.4`pa_stream_update_timing_info+0x153
libpulse.so.0.12.4`0x80f424b92
libpulse.so.0.12.4`0x80f42b96b
libpulse.so.0.12.4`pa_mainloop_dispatch+0x12b
libpulse.so.0.12.4`pa_mainloop_iterate+0x3a
libpulse.so.0.12.4`pa_mainloop_run+0x20
libpulse.so.0.12.4`0x80f42c24c
libpulsecommon-0.9.23.so`0x80f67a477
libthr.so.3`0x8028034f5
3 59411 memset:entry
libc.so.7`memset+0x1
libc.so.7`__calloc+0xf52
libpulse.so.0.12.4`pa_xmalloc0+0x25
libpulse.so.0.12.4`0x80f41ea26
libpulsecommon-0.9.23.so`pa_pdispatch_register_reply+0xc7
libpulse.so.0.12.4`pa_stream_update_timing_info+0x153
libpulse.so.0.12.4`0x80f424b92
libpulse.so.0.12.4`0x80f42b96b
libpulse.so.0.12.4`pa_mainloop_dispatch+0x12b
libpulse.so.0.12.4`pa_mainloop_iterate+0x3a
libpulse.so.0.12.4`pa_mainloop_run+0x20
libpulse.so.0.12.4`0x80f42c24c
libpulsecommon-0.9.23.so`0x80f67a477
libthr.so.3`0x8028034f5
etc...
Code: Select all
# dtrace -s memset.d 3228
dtrace: script 'memset.d' matched 2 probes
CPU ID FUNCTION:NAME
1 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 11:55:25
libc.so.7`memset+0x1
libc.so.7`__calloc+0xf52
64 7
1 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 11:55:35
libc.so.7`memset+0x1
libc.so.7`__calloc+0xf52
64 6
1 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 11:55:45
libc.so.7`memset+0x1
libc.so.7`__calloc+0xf52
64 7
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 1/ { ustack(); }' -p 3228
2 59411 memset:entry
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0xff
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
2 59411 memset:entry
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0x194
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
2 59411 memset:entry
^Clibc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0xff
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
Code: Select all
# dtrace -s memset.d 3228
dtrace: script 'memset.d' matched 2 probes
CPU ID FUNCTION:NAME
3 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 12:01:48
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
1 16227
3 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 12:01:58
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
1 16200
3 59412 :tick-10sec
memset stack, size count Date: 2015 Jan 23 12:02:08
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
1 16173
Last edited by Tzeentch on 24 Jan 2015, 23:33, edited 3 times in total.
Re: Dtrace on Warzone
Perfect fit from overview, cross platform memory allocator which could be faster than existing - http://www.hoard.org/ & http://people.cs.umass.edu/~emery/pubs/ ... os2000.pdf would need someone more experienced with warzone to advise, perhaps testing to compare is worthwhile if memory operations are of concern
Re: Dtrace on Warzone
Actually, the cause for our signficant CPU usage as shown here (no time to update post)
This top output was taken in the tutorial and checking the dtrace output from before with the 1 byte operations (second most common) shows this is something to do with displayConsoleMessages. (tutorial always has messages at top of screen) so if you compare
Against a 4 player match with 3 nexus AI's
and dtrace on this for memset operations shows
Disregard the count but focusing on the distribution of memsets, (as sampling times different) shows much less 1 byte memset operations, decreasing these syscalls helps reduce CPU usage almost double.
Code: Select all
CPU 0: 10.2% user, 0.0% nice, 2.8% system, 0.4% interrupt, 86.6% idle
CPU 1: 3.1% user, 0.0% nice, 2.7% system, 2.4% interrupt, 91.8% idle
CPU 2: 20.8% user, 0.0% nice, 1.2% system, 0.0% interrupt, 78.0% idle
CPU 3: 14.9% user, 0.0% nice, 1.6% system, 0.4% interrupt, 83.1% idle
Mem: 754M Active, 416M Inact, 1209M Wired, 12M Cache, 13G Free
ARC: 701M Total, 262M MFU, 400M MRU, 16K Anon, 3585K Header, 34M Other
Swap: 4096M Total, 4096M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
1025 scott 8 20 0 494M 183M usem 0 1:59 40.77% warzone2100
960 scott 1 27 0 823M 308M CPU2 2 1:09 13.96% kdeinit4
Code: Select all
# dtrace -n 'pid$target::memset:entry { @ = quantize(arg2); }' -p 3228
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@ 31840
2 |@@@@@@ 27353
4 |@@@@ 18915
8 |@ 4175
16 |@ 3307
32 |@@ 7280
64 |@@@@@@@@@@@@ 51411
128 |@@ 8623
256 |@@@ 13149
512 | 16
1024 |@@ 7563
2048 | 4
4096 |@ 3756
8192 | 1040
16384 | 115
32768 | 0
Code: Select all
CPU 0: 8.2% user, 0.0% nice, 2.7% system, 0.4% interrupt, 88.6% idle
CPU 1: 1.2% user, 0.0% nice, 2.8% system, 1.6% interrupt, 94.5% idle
CPU 2: 9.0% user, 0.0% nice, 3.1% system, 0.0% interrupt, 87.8% idle
CPU 3: 8.2% user, 0.0% nice, 3.1% system, 0.4% interrupt, 88.2% idle
Mem: 764M Active, 419M Inact, 1215M Wired, 12M Cache, 13G Free
ARC: 702M Total, 263M MFU, 401M MRU, 144K Anon, 3590K Header, 34M Other
Swap: 4096M Total, 4096M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
1025 scott 8 20 0 498M 189M usem 2 4:04 17.38% warzone2100
960 scott 1 27 0 823M 308M select 3 1:57 11.96% kdeinit4
Code: Select all
# dtrace -n 'pid$target::memset:entry { @ = quantize(arg2); }' -p 1025
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@ 19398
2 |@ 16308
4 |@@ 41475
8 |@ 29866
16 |@@ 30466
32 | 6183
64 |@@@@@@@@@@@@@@@@@@@ 378680
128 |@@@ 61819
256 |@@@@@@ 121121
512 |@ 10595
1024 |@@@ 54381
2048 | 278
4096 |@@ 31682
8192 | 5276
16384 | 181
32768 | 1
65536 | 1
131072 | 0
262144 | 542
524288 | 0
Re: Dtrace on Warzone
So in games where massive battles are ongoing you'll get many messages displayed for units lost, research upgrades etc which will increase CPU. Given this console message is a specific part of the game hopefully it should be easier to recode\design to make less syscalls. Be good to have some sandbox mode where you can test and check specific functionality with limited variables involved, newcomers could use that for doing basic practice. Random thought.
Re: Dtrace on Warzone
Getting ustack from displayConsoleMessages (highly suspected) memsets for the 1,2 & 4 byte operations. Shouldn't this be able to be done using assignment statements rather than memsets?
Single byte operations, the most common and I could use some explanation as to whats going on here as this looks to all be very similar to me.
Then onto 2 bytes
Lastly 4 byte ops.
Single byte operations, the most common and I could use some explanation as to whats going on here as this looks to all be very similar to me.
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 1/ { @[ustack()] = count(); }' -p 73185
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0xff
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
4312
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0x194
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
4779
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 2/ { @[ustack()] = count(); }' -p 73185
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0xff
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
962
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0x194
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
10582
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 4/ { @[ustack()] = count(); }' -p 73185
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0xff
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
678
libc.so.7`memset+0x1
libfribidi.so.0.3.1`fribidi_get_par_embedding_levels+0xa94
libfribidi.so.0.3.1`fribidi_log2vis+0xc0
warzone2100`__glcConvertToVisualUcs4+0x2b8
warzone2100`glcMeasureString+0x87
warzone2100`iV_GetTextWidth(char const*)+0x1a
warzone2100`iV_DrawFormattedText(char const*, unsigned int, unsigned int, unsigned int, unsigned int)+0x194
warzone2100`displayConsoleMessages(void)+0x386
warzone2100`draw3DScene(void)+0x1fea
warzone2100`displayWorld(void)+0x2b0
warzone2100`gameLoop(void)+0xf9b
warzone2100`mainLoop(void)+0x7c
warzone2100`wzMain3(void)+0x4d
warzone2100`realmain(int, char**)+0xd64
warzone2100`_start+0x16f
ld-elf.so.1`0x80094b000
8250
Re: Dtrace on Warzone
Made a flame graph of this for memsets using commands here on tutorial viewtopic.php?f=32&t=12021&p=131009#p131009
http://i.imgur.com/btkYW2Z.png
It would seem in my case most of memset operations are called from:
* libopenal in separate threads
* libnvidiagl-core
Once we get into warzone mainLoop from here:
* syncDebug
* displayConsoleMessages
* updatePlayerPower
http://i.imgur.com/btkYW2Z.png
It would seem in my case most of memset operations are called from:
* libopenal in separate threads
* libnvidiagl-core
Once we get into warzone mainLoop from here:
* syncDebug
* displayConsoleMessages
* updatePlayerPower
Re: Dtrace on Warzone
Did the same steps after setting all graphics to the lowest values and disabling shaders. Memory set distribution model appears almost the same.