Too big numbers for fileslower

[pavel-odintsov]

Hello!

Please take a look on this:

sysdig -c fileslower 1
TIME                    PROCESS      TYPE     LAT(ms) FILE

2014-08-11 18:14:08.350 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.356 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.357 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.459 mysqld       read           2 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.467 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.468 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.475 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.482 apache2      read           2 /var/www/mariya/data/www/potomy.ru/10d93e5e992e490b1128907a66ea63f3/links.db
2014-08-11 18:14:08.495 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.502 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.585 mysqld       pread          1 /vz/root/53336/var/lib/mysql/eltib135_amazing/wp_post_views_realtime.MYD
2014-08-11 18:14:08.655 mysqld       read           2 /vz/root/47690/var/lib/mysql/yapona/b_iblock_element.MYD
2014-08-11 18:14:08.787 mysqld       read          23 /vz/root/39344/var/lib/mysql/turtlepowerru/infernoshout.MYD
2014-08-11 18:14:08.797 mysqld       read           9 /vz/root/39344/var/lib/mysql/turtlepowerru/infernoshout.MYD
2014-08-11 18:14:08.991 php-cgi      write          1 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.064 php-cgi      write          2 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.124 php-cgi      write          1 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.225 php-cgi      write          1 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.252 php-cgi      write          1 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.294 php-cgi      write          2 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.343 php-cgi      write          7 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:09.351 mysqld       read           2 /var/lib/mysql/spu@002dpenza/jp940_k2_items.MYD
2014-08-11 18:14:09.354 php-cgi      write          5 /var/www/spu-penza/data/www/spu-penza.ru/libraries/legacy/error/error.php
2014-08-11 18:14:10.506 mysqld       read           3 /vz/root/47584/var/lib/mysql/football/cms_stats.MYD
2014-08-11 18:14:10.520 mysqld       read           1 /vz/root/47584/var/lib/mysql/football/cms_stats.MYD
2014-08-11 18:14:10.597 apache2      read           5 /var/www/99link/data/mod-tmp/sess_04i68h4bahlq6pqv7vuqvk2lh5
2014-08-11 18:14:10.629 mysqld       read           3 /vz/root/47584/var/lib/mysql/football/cms_stats.MYD
2014-08-11 18:14:10.717 mysqld       read           2 /vz/root/47714/var/lib/mysql/ruiframe/engine_pos.MYD
2014-08-11 18:14:10.837 apache2      read        1436 /var/www/enod/data/www/forum.vsalde.ru/sources/classes/class_session.php
2014-08-11 18:14:10.874 apache2      write          1 /var/www/enod/data/www/forum.vsalde.ru/sources/classes/class_session.php
2014-08-11 18:14:10.887 apache2      write          1 /var/www/enod/data/www/forum.vsalde.ru/sources/classes/class_session.php
2014-08-11 18:14:11.143 mysqld       read          28 /var/lib/mysql/turtlepowerru/infernoshout.MYD
2014-08-11 18:14:11.332 mysqld       read           1 /var/lib/mysql/turtlepowerru/infernoshout.MYD
2014-08-11 18:14:11.334 mysqld       read           1 /var/lib/mysql/turtlepowerru/infernoshout.MYD
2014-08-11 18:14:11.380 mysqld       write          1 /tmp/MYCAhtGd
2014-08-11 18:14:11.404 mysqld       write          2 /tmp/MYCAhtGd
2014-08-11 18:14:11.408 mysqld       write          1 /tmp/MYCAhtGd
2014-08-11 18:14:11.415 mysqld       write          2 /tmp/MYCAhtGd
2014-08-11 18:14:11.421 mysqld       write          4 /tmp/MYCAhtGd
2014-08-11 18:14:11.430 mysqld       write          1 /tmp/MYCAhtGd

As you can see 1436 is very big time. This servers works fine and it can be real. Please check code :)

[gianlucaborello]

Would you be able by any chance to provide a trace file showing this possible misbehavior (even a very short subset of it if you want to filter out sensitive data)?

Thanks

[gianlucaborello]

@pavel-odintsov any update on this?

[pavel-odintsov]

It's really hard but I will try to do this. Thank you for interest!

[pavel-odintsov]

It's realy hard to reproduce because I can't run two sysdig simultaneously: one for sysdig with chisels and one without chisels:

I have big amount of system activity and got same issues:

 sysdig -c fileslower 5
TIME                    PROCESS      TYPE     LAT(ms) FILE
2014-09-09 16:09:02.061 awk          read          53 /usr/lib/php5/sessionclean
2014-09-09 16:09:02.061 xargs        read          53 /usr/lib/php5/sessionclean
2014-09-09 16:09:13.635 rs:main      write         18 /vz/root/1222/var/log/syslog
2014-09-09 16:09:18.652 rs:main      write          9 /vz/root/1222/var/log/syslog
2014-09-09 16:09:18.653 cleanup      write          9 /vz/root/1222/var/spool/postfix/incoming/643345.9994
2014-09-09 16:09:28.834 sshd         read        1936 /vz/root/1225/dev/null
2014-09-09 16:09:38.717 rs:main      write         10 /vz/root/1222/var/log/syslog
2014-09-09 16:09:40.431 sshd         write         40 /var/log/btmp
2014-09-09 16:09:50.354 zabbix_agent read           9 /proc/5254/cmdline
2014-09-09 16:10:01.292 postdrop     write          6 /vz/root/1202/dev/null

It's not and I/O issue because /dev/null is not an file:)

But when I run raw sysdig:

sysdig evt.type=write and fd.name=/var/log/btmp

I got normal results:

14785 16:19:50.381135243 4 mysqld (6169) < read res=4 data=.... 
14823 16:19:50.381473426 4 mysqld (6168) < read res=4 data=.... 
15005 16:19:50.381925476 4 mysqld (6170) < read res=4 data==... 
15057 16:19:50.382055908 4 mysqld (13001) < read res=4 data==... 
15523 16:19:50.383210902 10 mysqld (7168) < read res=4 data=.... 
15779 16:19:50.383687001 10 mysqld (7170) < read res=4 data==... 
21536 16:19:50.556228884 8 mysqld (6171) < read res=4 data=.... 
21640 16:19:50.556563477 8 mysqld (13002) < read res=4 data==... 
30197 16:19:50.764985792 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30198 16:19:50.764988705 2 sshd (371574) < read res=1 data=S 
30199 16:19:50.764989069 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30200 16:19:50.764989427 2 sshd (371574) < read res=1 data=S 
30201 16:19:50.764989657 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30202 16:19:50.764989968 2 sshd (371574) < read res=1 data=H 
30203 16:19:50.764990180 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30204 16:19:50.764990481 2 sshd (371574) < read res=1 data=- 
30205 16:19:50.764990695 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30206 16:19:50.764991058 2 sshd (371574) < read res=1 data=2 
30207 16:19:50.764991271 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30208 16:19:50.764991575 2 sshd (371574) < read res=1 data=. 
30209 16:19:50.764991789 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30210 16:19:50.764992135 2 sshd (371574) < read res=1 data=0 
30211 16:19:50.764992373 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30212 16:19:50.764992705 2 sshd (371574) < read res=1 data=- 
30213 16:19:50.764992916 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30214 16:19:50.764993234 2 sshd (371574) < read res=1 data=l 
30215 16:19:50.764993457 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30216 16:19:50.764993777 2 sshd (371574) < read res=1 data=i 
30217 16:19:50.764994084 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30218 16:19:50.764994397 2 sshd (371574) < read res=1 data=b 
30219 16:19:50.764994611 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30220 16:19:50.764994917 2 sshd (371574) < read res=1 data=s 
30221 16:19:50.764995130 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30222 16:19:50.764995447 2 sshd (371574) < read res=1 data=s 
30223 16:19:50.764995658 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30224 16:19:50.764995967 2 sshd (371574) < read res=1 data=h 
30225 16:19:50.764996183 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30226 16:19:50.764996506 2 sshd (371574) < read res=1 data=2 
30227 16:19:50.764996719 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30228 16:19:50.764997024 2 sshd (371574) < read res=1 data=_ 
30229 16:19:50.764997242 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30230 16:19:50.764997559 2 sshd (371574) < read res=1 data=1 
30231 16:19:50.764997770 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30232 16:19:50.764998100 2 sshd (371574) < read res=1 data=. 
30233 16:19:50.764998315 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30234 16:19:50.764998633 2 sshd (371574) < read res=1 data=4 
30235 16:19:50.764998845 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30236 16:19:50.764999152 2 sshd (371574) < read res=1 data=. 
30237 16:19:50.764999363 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30238 16:19:50.764999674 2 sshd (371574) < read res=1 data=3 
30239 16:19:50.764999889 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30240 16:19:50.765000199 2 sshd (371574) < read res=1 data=. 
30241 16:19:50.765000425 2 sshd (371574) > read fd=3(<f>/vz/root/1225/dev/null) size=1 
30242 16:19:50.765001631 2 sshd (371574) < read res=1 data=. 
38588 16:19:51.027251281 0 sshd (371575) > read fd=3(<f>/vz/root/1225/dev/null) size=8192 
38591 16:19:51.027254477 0 sshd (371575) < read res=808 [email protected],diffie-hellman-group-excha 
69372 16:19:51.172823553 8 mysqld (6280) < read res=4 data=.... 
69660 16:19:51.173266770 8 mysqld (6281) < read res=4 data==... 

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.