Dtrace on Warzone

For code related discussions and questions
Post Reply
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Dtrace on Warzone

Post by Tzeentch »

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..
Last edited by Tzeentch on 23 Jan 2015, 14:21, edited 1 time in total.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

Warzone memory requested sizes (bytes) from malloc, printed out into a Distribution graph using ASCI format.

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        
Warzone memory returned (bytes) from requested

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
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

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
Checked all realted malloc data later on... Curious about value 34359738368

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        
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..

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"
oops, need instead... seems to crash game

Code: Select all

# dtrace -n 'pid$target:libc.so.7:strcmp:entry { trace(copyinstr(arg0)); }' -p 57752 
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

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
something went wrong there.

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
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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.

Code: Select all

# dtrace -n 'pid$target:::entry { @[probefunc] = count(); }' -p 58558

# dtrace: description 'pid$target:::entry ' matched 39978 probes
Output to log file... see attached.
warzone-allprobes.txt
all probes list from Warzone
(102.03 KiB) Downloaded 346 times
Checking all probes against Warzone:

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
Then memset we're going to check

Code: Select all

dtrace -n 'pid$target::memset:entry { @[ustack()] = count(); }' -p 58558
Quite long so output to another file, bottom looked most interesting
memset-ustack.txt
(1.01 MiB) Downloaded 350 times
Last edited by Tzeentch on 06 Feb 2015, 02:22, edited 1 time in total.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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
User avatar
NoQ
Special
Special
Posts: 6226
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Dtrace on Warzone

Post by NoQ »

Quite long so output to another file, bottom looked most interesting
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.
When checking the sync issues using Dtrace..
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.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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 -
hotuser.txt
Output of hotuser script
(259.92 KiB) Downloaded 342 times
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%
Had a test only disabling Vsync, then again after re-enabling
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%
Re-enabled :

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%
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 :hmm: that said warzone CPU usage goes from 8%-40% regardless of Vsync, but do have highest settings enabled

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 
Because 64 seems most common, get stack trace of this, commonly shows same repeated entries as follows

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...
Used Custom script so that when bytes == 64 start with shallow stack traces and increase the depth only when necessary script attached for reference. -
memset-script-ustack.txt
(3.59 KiB) Downloaded 324 times

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
Then check 1 memset, second most common

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
Modified Custom script so that when bytes == 1 start with shallow stack traces and increase the depth only when necessary

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
^C
Last edited by Tzeentch on 24 Jan 2015, 23:33, edited 3 times in total.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

Actually, the cause for our signficant CPU usage as shown here (no time to update post)

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
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

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 
Against a 4 player match with 3 nexus AI's

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
and dtrace on this for memset operations shows

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  
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.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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.
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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.

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
Then onto 2 bytes

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
Lastly 4 byte ops.

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
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

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
User avatar
Tzeentch
Trained
Trained
Posts: 309
Joined: 14 Oct 2012, 14:24

Re: Dtrace on Warzone

Post by Tzeentch »

Did the same steps after setting all graphics to the lowest values and disabling shaders. Memory set distribution model appears almost the same.
Post Reply