Skip to content
This repository has been archived by the owner on Feb 9, 2021. It is now read-only.

High disk IO on v1.5 #3067

Closed
beetree opened this issue May 25, 2015 · 6 comments
Closed

High disk IO on v1.5 #3067

beetree opened this issue May 25, 2015 · 6 comments

Comments

@beetree
Copy link

beetree commented May 25, 2015

I'm experiencing a problem that has been troubling me over the last few days. When running a 1.5 server (build 1156, but I think it's in all builds) after a while the disk IO climbs until it's at 99.99% and the machine essentially comes to a halt (cpu load >> 5 per core).

[root@ip-172-30-3-207 ~]# iotop -o --batch -n 1
Total DISK READ: 0.00 B/s | Total DISK WRITE: 375.81 K/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
17272 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
28749 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
32615 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
14400 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
28377 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
26709 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
29019 be/4 leet        0.00 B/s   53.69 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php

[root@ip-172-30-3-207 ~]# ls -l /proc/$(pgrep -f PocketMine)/fd
ls: cannot access 31772: No such file or directory
ls: cannot access 32406: No such file or directory
ls: cannot access 32615/fd: No such file or directory
/proc/528:
total 0
dr-xr-xr-x 2 leet leet 0 May 25 21:35 attr
-r-------- 1 leet leet 0 May 25 21:35 auxv
-r--r--r-- 1 leet leet 0 May 25 21:35 cgroup
--w------- 1 leet leet 0 May 25 21:35 clear_refs
-r--r--r-- 1 leet leet 0 May 25 07:02 cmdline
-rw-r--r-- 1 leet leet 0 May 25 21:35 comm
-rw-r--r-- 1 leet leet 0 May 25 21:35 coredump_filter
-r--r--r-- 1 leet leet 0 May 25 21:35 cpuset
lrwxrwxrwx 1 leet leet 0 May 25 21:35 cwd -> /home/leet/containers/11208/bundle
-r-------- 1 leet leet 0 May 25 21:35 environ
lrwxrwxrwx 1 leet leet 0 May 25 07:02 exe -> /home/leet/containers/11208/bundle/bin/php5/bin/php
dr-x------ 2 leet leet 0 May 25 21:35 fd
dr-x------ 2 leet leet 0 May 25 21:35 fdinfo
-rw-r--r-- 1 leet leet 0 May 25 21:35 gid_map
-r-------- 1 leet leet 0 May 25 21:35 io
-r--r--r-- 1 leet leet 0 May 25 21:35 latency
-r--r--r-- 1 leet leet 0 May 25 21:35 limits
-rw-r--r-- 1 leet leet 0 May 25 21:35 loginuid
-r--r--r-- 1 leet leet 0 May 25 21:35 maps
-rw------- 1 leet leet 0 May 25 21:35 mem
-r--r--r-- 1 leet leet 0 May 25 21:35 mountinfo
-r--r--r-- 1 leet leet 0 May 25 21:35 mounts
-r-------- 1 leet leet 0 May 25 21:35 mountstats
dr-xr-xr-x 5 leet leet 0 May 25 21:35 net
dr-x--x--x 2 leet leet 0 May 25 21:35 ns
-r--r--r-- 1 leet leet 0 May 25 21:35 numa_maps
-rw-r--r-- 1 leet leet 0 May 25 21:35 oom_adj
-r--r--r-- 1 leet leet 0 May 25 21:35 oom_score
-rw-r--r-- 1 leet leet 0 May 25 21:35 oom_score_adj
-r--r--r-- 1 leet leet 0 May 25 21:35 pagemap
-r--r--r-- 1 leet leet 0 May 25 21:35 personality
-rw-r--r-- 1 leet leet 0 May 25 21:35 projid_map
lrwxrwxrwx 1 leet leet 0 May 25 21:35 root -> /
-rw-r--r-- 1 leet leet 0 May 25 21:35 sched
-r--r--r-- 1 leet leet 0 May 25 21:35 schedstat
-r--r--r-- 1 leet leet 0 May 25 21:35 sessionid
-rw-r--r-- 1 leet leet 0 May 25 21:35 setgroups
-r--r--r-- 1 leet leet 0 May 25 21:35 smaps
-r--r--r-- 1 leet leet 0 May 25 21:35 stack
-r--r--r-- 1 leet leet 0 May 25 07:02 stat
-r--r--r-- 1 leet leet 0 May 25 19:21 statm
-r--r--r-- 1 leet leet 0 May 25 07:02 status
-r--r--r-- 1 leet leet 0 May 25 21:35 syscall
dr-xr-xr-x 7 leet leet 0 May 25 18:00 task
-rw-r--r-- 1 leet leet 0 May 25 21:35 uid_map
-r--r--r-- 1 leet leet 0 May 25 21:35 wchan

Default pocketmine.yml and server.properties.

Would love to get some help on this!
@beetree
Copy link
Author

beetree commented May 25, 2015

Here is a better dump:

[root@ip-172-30-3-207 ~]# iotop -o --batch -n 1
Total DISK READ: 0.00 B/s | Total DISK WRITE: 395.01 K/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
28749 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
11933 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
31518 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
30371 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
28377 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
 1055 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php
19463 be/4 leet        0.00 B/s   49.38 K/s  0.00 % 99.99 % ./bin/php5/bin/php src/pocketmine/PocketMine.php

[root@ip-172-30-3-207 ~]# ls -l /proc/28377/fd
total 0
lr-x------ 1 leet leet 64 May 25 21:43 0 -> /dev/null
l-wx------ 1 leet leet 64 May 25 21:43 1 -> /dev/null
lrwx------ 1 leet leet 64 May 25 21:43 10 -> /tmp/phpB7hSNB
lrwx------ 1 leet leet 64 May 25 21:43 11 -> /tmp/phpBtZh29
lrwx------ 1 leet leet 64 May 25 21:43 12 -> socket:[9686264]
l-wx------ 1 leet leet 64 May 25 21:43 2 -> /dev/null
lrwx------ 1 leet leet 64 May 25 21:43 3 -> /home/leet/containers/20907/bundle/server.log
lrwx------ 1 leet leet 64 May 25 21:43 4 -> /home/leet/containers/20907/bundle/plugins/essentialsTP/essentials_tp.db
lrwx------ 1 leet leet 64 May 25 21:43 5 -> socket:[9686256]
lrwx------ 1 leet leet 64 May 25 21:43 7 -> /tmp/phpKUm66W
lrwx------ 1 leet leet 64 May 25 21:43 8 -> /tmp/phpu7nglv
lrwx------ 1 leet leet 64 May 25 21:43 9 -> /tmp/phpBaWuz3

@beetree
Copy link
Author

beetree commented May 25, 2015

server.log:

[root@ip-172-30-3-207 ~]# tail -c 1000 /home/leet/containers/20907/bundle/server.log
aded?
2015-05-25 21:47:04 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:47:18 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:47:29 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:47:40 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:47:51 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:48:02 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:48:14 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:48:26 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:48:39 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:48:52 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:49:04 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:49:38 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:49:59 [WARNING] Can't keep up! Is the server overloaded?
2015-05-25 21:50:17 [WARNING] Can't keep up! Is the server overloaded?

@beetree
Copy link
Author

beetree commented May 25, 2015

[root@ip-172-30-3-207 ~]# strace -e trace=file -p 26597
Process 26597 attached
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 12
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 12
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 12
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 12
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 12
lstat("/proc/self/status", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
open("/proc/26597/status", O_RDONLY) = 12
lstat("/proc/self/status", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
open("/proc/26597/status", O_RDONLY) = 12
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud/ItemCloud.dat", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lstat("/home/leet/containers/21080/bundle/plugins/ItemCloud", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

@beetree
Copy link
Author

beetree commented May 25, 2015 

[leet@ip-172-30-3-207 bundle]$ cat timings/timings.txt
Minecraft
    ** Full Server Tick Time: 11810303 Count: 80 Avg: 147629 Violations: 0
    Memory Manager Time: 619411 Count: 81 Avg: 7647 Violations: 0
    Connection Handler Time: 1551390 Count: 81 Avg: 19153 Violations: 0
    Scheduler Time: 1526833 Count: 81 Avg: 18850 Violations: 0
    Server Command Time: 1453638 Count: 80 Avg: 18170 Violations: 0
    ** tickEntity Time: 148773 Count: 81 Avg: 1837 Violations: 0
    ** tickTileEntity Time: 132799 Count: 81 Avg: 1639 Violations: 0
    ** Scheduler - Sync Tasks Time: 62704 Count: 4 Avg: 15676 Violations: 0
    ** Scheduler - Async Tasks Time: 337601 Count: 81 Avg: 4168 Violations: 0
    ** world - doTickPending Time: 211716 Count: 81 Avg: 2614 Violations: 0
    ** world - doTickTiles Time: 389338 Count: 81 Avg: 4807 Violations: 0
    ** world - entityTick Time: 420809 Count: 81 Avg: 5195 Violations: 0
    ** world - tileEntityTick Time: 371695 Count: 81 Avg: 4589 Violations: 0
    world - doTick Time: 2647877 Count: 81 Avg: 32690 Violations: 0
    Task: LeetBorder v1.0.1 Runnable: Leet\LeetBorder\task\BorderCheckTask(interval:20) Time: 53883 Count: 4 Avg: 13471 Violations: 0
# Version v0.11.0 alpha build 12
# PocketMine-MP 1.5dev-1156
# Entities 0
# LivingEntities 0
Sample time 4049777985 (4.0497779846191s)

@beetree
Copy link
Author

beetree commented May 25, 2015

CODE
Minecraft
** Full Server Tick Time: 11810303 Count: 80 Avg: 147629 Violations: 0
Memory Manager Time: 619411 Count: 81 Avg: 7647 Violations: 0
Connection Handler Time: 1551390 Count: 81 Avg: 19153 Violations: 0
Scheduler Time: 1526833 Count: 81 Avg: 18850 Violations: 0
Server Command Time: 1453638 Count: 80 Avg: 18170 Violations: 0
** tickEntity Time: 148773 Count: 81 Avg: 1837 Violations: 0
** tickTileEntity Time: 132799 Count: 81 Avg: 1639 Violations: 0
** Scheduler - Sync Tasks Time: 62704 Count: 4 Avg: 15676 Violations: 0
** Scheduler - Async Tasks Time: 337601 Count: 81 Avg: 4168 Violations: 0
** world - doTickPending Time: 211716 Count: 81 Avg: 2614 Violations: 0
** world - doTickTiles Time: 389338 Count: 81 Avg: 4807 Violations: 0
** world - entityTick Time: 420809 Count: 81 Avg: 5195 Violations: 0
** world - tileEntityTick Time: 371695 Count: 81 Avg: 4589 Violations: 0
world - doTick Time: 2647877 Count: 81 Avg: 32690 Violations: 0
Task: LeetBorder v1.0.1 Runnable: Leet\LeetBorder\task\BorderCheckTask(interval:20) Time: 53883 Count: 4 Avg: 13471 Violations: 0

Version v0.11.0 alpha build 12

PocketMine-MP 1.5dev-1156

Entities 0

LivingEntities 0

Sample time 4049777985 (4.0497779846191s)
[leet@ip-172-30-3-207 bundle]$ cat timings/timings.txt
Minecraft
** Full Server Tick Time: 11810303 Count: 80 Avg: 147629 Violations: 0
Memory Manager Time: 619411 Count: 81 Avg: 7647 Violations: 0
Connection Handler Time: 1551390 Count: 81 Avg: 19153 Violations: 0
Scheduler Time: 1526833 Count: 81 Avg: 18850 Violations: 0
Server Command Time: 1453638 Count: 80 Avg: 18170 Violations: 0
** tickEntity Time: 148773 Count: 81 Avg: 1837 Violations: 0
** tickTileEntity Time: 132799 Count: 81 Avg: 1639 Violations: 0
** Scheduler - Sync Tasks Time: 62704 Count: 4 Avg: 15676 Violations: 0
** Scheduler - Async Tasks Time: 337601 Count: 81 Avg: 4168 Violations: 0
** world - doTickPending Time: 211716 Count: 81 Avg: 2614 Violations: 0
** world - doTickTiles Time: 389338 Count: 81 Avg: 4807 Violations: 0
** world - entityTick Time: 420809 Count: 81 Avg: 5195 Violations: 0
** world - tileEntityTick Time: 371695 Count: 81 Avg: 4589 Violations: 0
world - doTick Time: 2647877 Count: 81 Avg: 32690 Violations: 0
Task: LeetBorder v1.0.1 Runnable: Leet\LeetBorder\task\BorderCheckTask(interval:20) Time: 53883 Count: 4 Avg: 13471 Violations: 0

Version v0.11.0 alpha build 12

PocketMine-MP 1.5dev-1156

Entities 0

LivingEntities 0

Sample time 4049777985 (4.0497779846191s)

@beetree
Copy link
Author

beetree commented May 25, 2015

Confirmed. This was an issue in ItemCloud.

Shoghicp suggested error is here: https://github.com/onebone/ItemCloud/blob/master/src/onebone/itemcloud/MainClass.php#L62

@beetree beetree closed this as completed May 25, 2015
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@beetree