Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Too big numbers for fileslower #224

Open
pavel-odintsov opened this issue Aug 11, 2014 · 5 comments
Open

Too big numbers for fileslower #224

pavel-odintsov opened this issue Aug 11, 2014 · 5 comments
Labels
needs-investigation pinned

Comments

@pavel-odintsov
Copy link
Contributor

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 :)
@pavel-odintsov pavel-odintsov changed the title Too bug numbers for fileslower Too big numbers for fileslower Aug 11, 2014
@gianlucaborello
Copy link
Contributor

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
Copy link
Contributor

@pavel-odintsov any update on this?

@pavel-odintsov
Copy link
Contributor Author

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

@pavel-odintsov
Copy link
Contributor Author

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

github-actions bot commented Mar 2, 2023

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.

@github-actions github-actions bot added the stale label Mar 2, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
needs-investigation pinned
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@pavel-odintsov @gianlucaborello @therealbobo