mocchira
commented
7 years ago @vstax Thank for the further testing!
I've found the other problems that cause state inconsistencies to happen between storage(s) and manager(s) and also the problem that cause gen_server to crash frequently on your storage_0 thanks to your report.
The fixes are already out there.
Please try those fixes with the clean state once the above PRs get merged.
I've also confirmed that my assumption from previous comment (#725 (comment)) is correct and counters on storage_1 really went off during that bucket deletion experiment; they were fine on storage_0, however. I rolled back to original state and did compaction on storage_1 to verify counters, and values were the same. That means that there was no error before the experiment, and the error (2035 remaining objects per counters, while in reality there were 0 left) appeared during the course of bucket deletion.
Thanks. I will vet.
Another note: looks like delete-bucket-stats automatically wipes the stats some time after state is "finished" for all nodes (not sure when, 1 or 2 hours maybe?). Which is fine but probably should be mentioned in documentation for that command so that no one gets confused?
Thanks for pointing that out, we will mention about it in doc.
vstax
yosukehara
I got test cluster (1.3.4, 3 storage nodes, N=2, W=1). There are two buckets, "body" and "bodytest", each containing the same objects, about 1M in each (there are some other buckets as well, but they hardly contain anything). In other words, there are slightly over 2M objects in cluster in total. At the start of this test the data is fully consistent. There is some minor load on cluster with "body" buckets - some PUT & GET operations, but very few of them. No one tries to access "bodytest" bucket.
I want to remove "bodytest" with all its objects. I execute
s3cmd rb s3://bodytest. I see load on gateway and storage nodes; after some time, s3cmd fails because of timeout (I expect this to happen, no way storage can find all 1M objects and mark them as deleted fast enough). I seeleo_async_deletion_queuequeues growing on storage nodes:[root@leo-m0 ~]# /usr/local/bin/leofs-adm mq-stats storage_2@192.168.3.55|grep leo_async_deletion_queue leo_async_deletion_queue | idling | 97845 | 0 | 3000 | async deletion of objs [root@leo-m0 ~]# /usr/local/bin/leofs-adm mq-stats storage_2@192.168.3.55|grep leo_async_deletion_queue leo_async_deletion_queue | idling | 102780 | 0 | 3000 | async deletion of objs [root@leo-m0 ~]# /usr/local/bin/leofs-adm mq-stats storage_2@192.168.3.55|grep leo_async_deletion_queue leo_async_deletion_queue | idling | 104911 | 0 | 3000 | async deletion of objs [root@leo-m0 ~]# /usr/local/bin/leofs-adm mq-stats storage_2@192.168.3.55|grep leo_async_deletion_queue leo_async_deletion_queue | idling | 108396 | 0 | 3000 | async deletion of objs
The same for storage_0 and storage_1. There is hardly any disk load, each storage nodes consumes 120-130% CPU as per
top.Then some errors appear in error log on gateway_0:
If these errors mean that gateway sent "timeout" to the client that requested "delete bucket" operation, plus some other timeouts due to load on system - then it's within expectations; as long as all data from that bucket will eventually be marked as "deleted" asynchronously, all is fine.
That's not what happens, however. At some point - few minutes after the "delete bucket" operation - delete queues stop growing or reducing. It's as if they are stuck. Here is their current state - 1.5 hours after the experiment; they got to that state within 5-10 minutes after start of experiment and never changed since (I show only one queue here, others are empty):
There is nothing in logs of manager nodes. There is nothing in
erlang.logfiles on storage nodes (no mention of restarts or anything). Logs on storage nodes, info log for storage_0:error log on storage_0:
Info log on storage_1:
error log on storage_1:
Info log on storage_2:
Error log on storage_2:
To summarize the problems:
and on storage_0:
What happened here - it's that "minor load" that I mentioned. Basically at 17:17:13 application tried to do PUT operation of object
body/08/08/e2/0808e2f9815aa7d4b9c92b01db4fa208344d063d83c151b5349095f4004b60e1684056dab62f9bc2b51ac0e6b3721ca6a807010000000000.xz. That's a very small object, 27 KB in size. Some moments after successful PUT few (5, I believe) other applications did GET for that object. However, they all were using the same gateway with caching enabled, so they should've gotten the object from memory cache (at worst gateway would've checked ETag against storage node). 17:17:13 was in the middle of "delete bucket" operation, so I suppose the fact that there was large "processing time" for PUT was expected. But why "read_repairer" errors and "primary_inconsistency"?? Storage_0 is "primary" node for this object: