Dtrace Vsync
Posted: 07 Feb 2015, 02:30
It has been said to me (along with evidence, specifically this point viewtopic.php?f=32&t=11978#p130616) that performance issues ( more CPU activity) occurs when Vsync is disabled, as memset() operations are dramatically higher.
Thus soon as I disable Vsync CPU usage climbs all the way up to 100% from the main menu!!
Checking memset entry points with Vsync disabled, while in the main menu (CPU constantly at 100%)
8 being the most common operation, printing this out with user-space stack trace.
And due to system % in top output then checked time spent in Syscalls from main menu
Decided to try a skirmish game vs 3 Nexus AI's , Vsync still disabled and quite different memset operations but CPU remains very high, (100-110%):
Again user-space stack trace for most common operations.
Syscalls (nano timestamps) during vs 3 Nexus AI's.
This to me shows that Noq's right as memsets are much more frequent, and CPU becomes the bottleneck as an effect. It would be useful to view the amount of frames my machine is attempting to display. Being as I've got a high end graphics card I wonder if this is displaying very high frames and causing the CPU to not be able to keep up with the amount of frequent calls being made. Their wouldn't be much point trying to produce more frames than 60fps as this is the most the human eye is able to view and many monitors only support 60hz ( refresh screen 60 times a second ) so maybe a limit to max of 60 either way
Also obtained a Flame Graph but having issue attaching to tickets
Thus soon as I disable Vsync CPU usage climbs all the way up to 100% from the main menu!!
Code: Select all
last pid: 2407; load averages: 1.38, 0.98, 0.59 up 0+04:36:32 23:37:41
100 processes: 1 running, 98 sleeping, 1 zombie
CPU 0: 8.6% user, 0.0% nice, 8.2% system, 0.0% interrupt, 83.1% idle
CPU 1: 5.9% user, 0.0% nice, 4.3% system, 3.1% interrupt, 86.7% idle
CPU 2: 35.7% user, 0.0% nice, 12.5% system, 0.0% interrupt, 51.8% idle
CPU 3: 24.3% user, 0.0% nice, 12.2% system, 0.4% interrupt, 63.1% idle
Mem: 2399M Active, 3537M Inact, 3075M Wired, 5064K Cache, 6873M Free
ARC: 2270M Total, 1441M MFU, 776M MRU, 18K Anon, 26M Header, 27M Other
Swap: 2048M Total, 2048M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
2364 scott 5 20 0 390M 94336K usem 0 5:57 100.00% warzone2100
794 root 1 23 0 3261M 69444K select 0 5:43 5.96% Xorg
Code: Select all
# dtrace -n 'pid$target::memset:entry { @ = quantize(arg2); }' -p 2364
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
2 | 0
4 |@@ 285216
8 |@@@@@@@@@@@@@@ 1853903
16 |@@ 228172
32 |@@ 285216
64 |@@@@@@@@@ 1184353
128 |@@ 222909
256 |@@ 330111
512 |@@@@@ 688332
1024 |@@@ 350560
2048 | 0
4096 | 7118
8192 | 1188
16384 | 0
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 8/ { ustack(); }' -p 2364
2 59411 memset:entry
libc.so.7`memset+0x1
libfreetype.so.6.11.2`ft_mem_realloc+0x86
libfreetype.so.6.11.2`FT_CMap_New+0x104
libfreetype.so.6.11.2`0x80237ab68
libfreetype.so.6.11.2`0x802376e20
libfreetype.so.6.11.2`0x8023429b7
libfreetype.so.6.11.2`0x8023328da
libfreetype.so.6.11.2`FT_Open_Face+0x254
libfreetype.so.6.11.2`FT_New_Face+0x2e
warzone2100`__glcFaceDescOpen+0x6b
warzone2100`glcFont+0x9a
warzone2100`displayTextOption(WIDGET*, unsigned int, unsigned int, PIELIGHT*)+0x2a
warzone2100`0x601718
warzone2100`0x601703
warzone2100`0x601703
warzone2100`widgDisplayScreen(W_SCREEN*)+0x50
warzone2100`runTitleMenu(void)+0x1b1
warzone2100`titleLoop(void)+0x148
warzone2100`mainLoop(void)+0x44
warzone2100`wzMain3(void)+0x4d
2 59411 memset:entry
libc.so.7`memset+0x1
libfreetype.so.6.11.2`ft_mem_realloc+0x86
libfreetype.so.6.11.2`FT_CMap_New+0x104
libfreetype.so.6.11.2`0x80237ab68
libfreetype.so.6.11.2`0x802376e20
libfreetype.so.6.11.2`0x8023429b7
libfreetype.so.6.11.2`0x8023328da
libfreetype.so.6.11.2`FT_Open_Face+0x254
libfreetype.so.6.11.2`FT_New_Face+0x2e
warzone2100`__glcFaceDescOpen+0x6b
warzone2100`glcFont+0x9a
warzone2100`displayTextOption(WIDGET*, unsigned int, unsigned int, PIELIGHT*)+0x2a
warzone2100`0x601718
warzone2100`0x601703
warzone2100`0x601703
warzone2100`widgDisplayScreen(W_SCREEN*)+0x50
warzone2100`runTitleMenu(void)+0x1b1
warzone2100`titleLoop(void)+0x148
warzone2100`mainLoop(void)+0x44
warzone2100`wzMain3(void)+0x4d
2 59411 memset:entry
libc.so.7`memset+0x1
libfreetype.so.6.11.2`ft_mem_realloc+0x86
libfreetype.so.6.11.2`FT_CMap_New+0x104
libfreetype.so.6.11.2`0x80237ab68
libfreetype.so.6.11.2`0x802376e20
libfreetype.so.6.11.2`0x8023429b7
libfreetype.so.6.11.2`0x8023328da
libfreetype.so.6.11.2`FT_Open_Face+0x254
libfreetype.so.6.11.2`FT_New_Face+0x2e
warzone2100`__glcFaceDescOpen+0x6b
warzone2100`glcFont+0x9a
warzone2100`displayTextOption(WIDGET*, unsigned int, unsigned int, PIELIGHT*)+0x2a
warzone2100`0x601718
warzone2100`0x601703
warzone2100`0x601703
warzone2100`widgDisplayScreen(W_SCREEN*)+0x50
warzone2100`runTitleMenu(void)+0x1b1
warzone2100`titleLoop(void)+0x148
warzone2100`mainLoop(void)+0x44
warzone2100`wzMain3(void)+0x4d
Code: Select all
# /usr/share/dtrace/toolkit/procsystime -n warzone2100
Elapsed Times for processes warzone2100,
SYSCALL TIME (ns)
write 318103
sendto 861108
read 1178832
getpid 9493368
select 12269129
recvmsg 13732521
fcntl 20031746
sched_yield 29221444
fstat 66409512
close 70381193
sigprocmask 83982928
mmap 204389463
open 302234442
munmap 376817672
poll 5070627482
_umtx_op 5241236355
nanosleep 5658388868
Code: Select all
# dtrace -n 'pid$target::memset:entry { @ = quantize(arg2); }' -p 2471
dtrace: description 'pid$target::memset:entry ' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@ 39955
2 |@ 33772
4 |@@@ 98280
8 | 5824
16 |@ 34940
32 | 8
64 |@@@@@@@@@@@@@@@@@@@@@@@@@ 878290
128 |@@@ 121742
256 |@@@ 100907
512 | 67
1024 |@@@ 112253
2048 | 12
4096 | 5446
8192 | 1085
16384 | 40
32768 | 0
65536 | 1243
131072 | 0
Again user-space stack trace for most common operations.
Code: Select all
# dtrace -n 'pid$target::memset:entry /arg2 == 64/ { ustack(); }' -p 2471
dtrace: description 'pid$target::memset:entry ' matched 1 probe
CPU ID FUNCTION:NAME
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
2 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
Code: Select all
# /usr/share/dtrace/toolkit/procsystime -n warzone2100
Tracing... Hit Ctrl-C to end...
^C
Elapsed Times for processes warzone2100,
SYSCALL TIME (ns)
sigprocmask 1064
writev 7905
write 639880
sendto 1667371
read 2461483
getpid 10656228
select 11675878
recvmsg 13243572
sched_yield 97018093
poll 10328725562
nanosleep 10635305240
_umtx_op 33636475465
Also obtained a Flame Graph but having issue attaching to tickets