Match Savings, or Elusive Joe Returns
This article does not claim originality or novelty, but only opens the hood in this hellish optimization machine .
After reading the article by comrade pavlinux a couple of days ago, I was very intrigued, because just last night I discovered readahead and, having twisted the faucets, I got redundant (from the point of view of the ideology of this program) caching and with it reactive loading and profile entry. It was thought, why not squeeze out of a modest typewriter based on Intel Atom a little more?
It so happened that, in addition to ssh and telnet, in my work I often use a web browser, then I will arrange it for lice check. Let's forget the holy wars about “which browser is the best”: today Google Chrome 29.0.1547.62 (r219432) falls under the knife.
Since your humble servant is a level 1 script writer, I will use bash for a small support script:
I will be glad to your comments in the comments.
')
Also, we will create the Spartan conditions for the test in advance - we will clear the browser cache and at the same time the system one ( pagecache , dentries and inodes ):
We launch the browser and open a lot of tabs from a variety of sites overloaded with content. I know that you always do that, which means that the situation is quite regular.
For some, the usual picture, but for me it is stressful.
After sourcing some time (in my case it took a little over an hour - I could not bear any more), close the browser and begin to parse the output:
Merge all the trace files into one and sort:
Remove from the output lines that are not related to calls ("+++ exited with 0 +++" and their ilk):
Select only the lines from the file when the call failed (thanks for the pavlinux hint):
The percentage of failed calls is 16.418%.
Quite a lot, but let's take a deeper look and find out the statistics of failures:
It turns out that in addition to unsuccessful open and stat64, there is also access and readlinkat .
All this is interesting, of course, and worthy of a more detailed analysis,
But it's time to find out how much time is spent on these most unfortunate challenges.
Select from the file the specific values ​​of the call execution time:
Now our task is to get the sum of almost 40 thousand values. I was too lazy and took the ready code from here :
Run this code:
The result is a bit predictable: the unsuccessful system calls of Google Chrome and all processes launched by it spent 4 seconds.
The actual lead time is 1 hour 11 minutes and 55 seconds, or 4315 seconds.
The percentage of "lost" time: 4/4315 = ~ 0,093%. Not even one percent, but one ppm with a slight stretch.
Let everyone decide for himself. On the one hand, it will never be superfluous to check frequently used applications / systems for this type of “lice” and find out where bottlenecks can be and how to deal with them. On the other hand, every action should have a measure, and pedantically paranoid optimization of library / file locations speeds up the launch of an application by a fraction of a second and perhaps even work, but it is still only a fraction of a second. They can be useful in systems that work with crazy uptime, as they will accumulate, but their value disappears in applications that run for a relatively short time. In the end, it all depends on your task and how much you value your own time.
To some extent, I do not value my time: I spent my sleep on researching this controversial issue and writing an article about the fact that “you shouldn’t stop the plane from flying”.
This article is intended not to humiliate fellow pavlinux or his article, but to point out the nuances left unattended. Moreover, without the first article I would not conduct nightly research andthink with my head to write my own.
PS: the very 4.17 seconds is the Elusive Joe.
Prehistory
After reading the article by comrade pavlinux a couple of days ago, I was very intrigued, because just last night I discovered readahead and, having twisted the faucets, I got redundant (from the point of view of the ideology of this program) caching and with it reactive loading and profile entry. It was thought, why not squeeze out of a modest typewriter based on Intel Atom a little more?
It so happened that, in addition to ssh and telnet, in my work I often use a web browser, then I will arrange it for lice check. Let's forget the holy wars about “which browser is the best”: today Google Chrome 29.0.1547.62 (r219432) falls under the knife.
Training
Since your humble servant is a level 1 script writer, I will use bash for a small support script:
trace_google_chrome
I sprinkle my head with ashes and repent, not the best example of a script for such a task.
#!/bin/bash ENV_EXCLUDE=('^SUDO_' '^GREP_' '^LS_' '^KONSOLE_' '^_$') ENV_PERSIST=('^PATH$' '^LOGNAME$' '^USER' '^HOME$') sudo true || return 1 T0=$(mktemp) sudo -E env | cut -d'=' -f1 | tee ${T0} &>/dev/null T1=$(mktemp) for i in ${ENV_EXCLUDE[@]}; do egrep -e "$i" < ${T0} >> ${T1}; done T2=$(mktemp) for i in ${ENV_PERSIST[@]}; do egrep -e "$i" < ${T0} >> ${T2}; done rm ${T0} STRACE_ARGS='' while read L; do STRACE_ARGS=${STRACE_ARGS}" -E $L" done < ${T1}; rm ${T1} while read L; do declare -p $L &>/dev/null || continue V=$(env | egrep -e ^$L) STRACE_ARGS=${STRACE_ARGS}" -E $V" done < ${T2}; rm ${T2} U=$(whoami) date --rfc-3339=ns >d.begin sudo -E strace -ff -o zzz -v -s 256 -T \ -u ${U} -E USERNAME=${U} ${STRACE_ARGS} \ -e trace=file,signal,ipc google-chrome date --rfc-3339=ns >d.end I will be glad to your comments in the comments.
')
Also, we will create the Spartan conditions for the test in advance - we will clear the browser cache and at the same time the system one ( pagecache , dentries and inodes ):
$ find .cache/google-chrome/ -mindepth 1 -delete $ sync $ sudo sysctl -w vm.drop_caches=3 vm.drop_caches = 3
Testing
We launch the browser and open a lot of tabs from a variety of sites overloaded with content. I know that you always do that, which means that the situation is quite regular.
$ trace_google_chrome Fontconfig warning: "/etc/fonts/conf.d/50-user.conf", line 9: reading configurations from ~/.fonts.conf is deprecated. [19883:19883:0904/013557:ERROR:profile_sync_service.cc(1240)] History Delete Directives, Sync Error: Delete directives not supported with encryption. Fontconfig warning: "/etc/fonts/conf.d/50-user.conf", line 9: reading configurations from ~/.fonts.conf is deprecated. [19883:19909:0904/013606:ERROR:native_backend_kwallet_x.cc(848)] Error obtaining KWallet handle ATTENTION: default value of option force_s3tc_enable overridden by environment. [WARNING:flash/platform/pepper/pep_module.cpp(63)] SANDBOXED [WARNING:flash/platform/pepper/pep_module.cpp(63)] SANDBOXED ATTENTION: default value of option force_s3tc_enable overridden by environment. ATTENTION: default value of option force_s3tc_enable overridden by environment.
For some, the usual picture, but for me it is stressful.
After sourcing some time (in my case it took a little over an hour - I could not bear any more), close the browser and begin to parse the output:
$ egrep -He^ d.* d.begin:2013-09-04 01:35:39.040184387+04:00 d.end:2013-09-04 02:57:34.084098826+04:00 $ du -ch zzz.* | tail -n 1 34M
Merge all the trace files into one and sort:
$ cat zzz.* > z $ sort < z > z.sorted $ wc -l < z.sorted 243048
Remove from the output lines that are not related to calls ("+++ exited with 0 +++" and their ilk):
$ egrep -ve '^\+' < z.sorted > z.clean $ wc -l < z.clean 242474
Select only the lines from the file when the call failed (thanks for the pavlinux hint):
$ fgrep -e ' = -' < z.clean > z.fail $ wc -l < z.fail 39810
The percentage of failed calls is 16.418%.
Quite a lot, but let's take a deeper look and find out the statistics of failures:
$ cut -d'(' -f1 < z.fail | uniq > z.fail.names $ cat z.fail.names | > while read SYSCALL; do > echo -n "${SYSCALL}:" > egrep -ce "^${SYSCALL}\(" z.fail > done access:16807 chmod:2 execve:56 faccessat:6 fstatat64:46 lstat64:91 mkdir:8 openat:155 open:7812 readlinkat:4909 readlink:86 rt_sigaction:59 rt_sigreturn:8 shmctl:1 sigreturn:47 stat64:9658 statfs64:39 unlink:20
It turns out that in addition to unsuccessful open and stat64, there is also access and readlinkat .
All this is interesting, of course, and worthy of a more detailed analysis,
But it's time to find out how much time is spent on these most unfortunate challenges.
Select from the file the specific values ​​of the call execution time:
$ sed -nre '/^.* <([0-9\.]+)>$/{s##\1#;p}' < z.fail > z.fail.timing
Now our task is to get the sum of almost 40 thousand values. I was too lazy and took the ready code from here :
#include <stdio.h> #include <stdlib.h> int main(void) { ssize_t read; char *line = NULL; size_t len = 0; double sum = 0.0; while (read = getline(&line, &len, stdin) != -1) { sum += atof(line); } printf("%f\n", sum); return 0; }
Run this code:
$ gcc sum.c -o sum; ./sum < z.fail.timing 4.173705
The result is a bit predictable: the unsuccessful system calls of Google Chrome and all processes launched by it spent 4 seconds.
The actual lead time is 1 hour 11 minutes and 55 seconds, or 4315 seconds.
The percentage of "lost" time: 4/4315 = ~ 0,093%. Not even one percent, but one ppm with a slight stretch.
findings
Let everyone decide for himself. On the one hand, it will never be superfluous to check frequently used applications / systems for this type of “lice” and find out where bottlenecks can be and how to deal with them. On the other hand, every action should have a measure, and pedantically paranoid optimization of library / file locations speeds up the launch of an application by a fraction of a second and perhaps even work, but it is still only a fraction of a second. They can be useful in systems that work with crazy uptime, as they will accumulate, but their value disappears in applications that run for a relatively short time. In the end, it all depends on your task and how much you value your own time.
To some extent, I do not value my time: I spent my sleep on researching this controversial issue and writing an article about the fact that “you shouldn’t stop the plane from flying”.
Afterword
This article is intended not to humiliate fellow pavlinux or his article, but to point out the nuances left unattended. Moreover, without the first article I would not conduct nightly research and
PS: the very 4.17 seconds is the Elusive Joe.
Source: https://habr.com/ru/post/192508/
All Articles