search

markfasheh / duperemove

Tools for deduping file systems
GNU General Public License v2.0
794 stars 78 forks source link

Database error 101 (no more rows available) on XFS #275

Closed dlight closed 1 year ago

dlight commented 2 years ago

Hello, I'm using duperemove on XFS without problems for a while.

But now, after calculating all hashes (from scratch, with no previous hash file), duperemove gives some scary warnings. After I noticed I entered ctrl+c. Can those warnings indicate there might be a chance of data corruption?

Total files:  113247
Total extent hashes: 158560
Loading only duplicated hashes from hashfile.
Found 36794 identical extents.
Using 8 threads to search within extents extents for additional dedupe. This process will take some time, during which Duperemove can safely be ctrl-c'd.
[%                                       ]dbfile_load_one_file_extent()/437048: Database error 101 while retrieving extent info: no more rows available
dbfile_load_one_file_extent()/437044: Database error 101 while retrieving extent info: no more rows available
[##%                                     ]dbfile_load_one_file_extent()/437048: Database error 101 while retrieving extent info: no more rows available
[###%                                    ]dbfile_load_one_file_extent()/437041: Database error 101 while retrieving extent info: no more rows available
[#####%                                  ]^C

I'm using duperemove v0.11.3 and this is the command line I used

duperemove -rdh --dedupe-options=partial,same --hashfile=hash /dir
lorddoskias commented 2 years ago

Hello, no this doesn't indicate there is data corruption it simply informs (albeit it might sound somewhat scary indeed) you that the partial search wasn't able to find a particular extent which satisfied the criteria for partial search. I guess it will be better if this is turned into something printed only when verbose output is requested.

dlight commented 2 years ago

Okay, thanks!

it simply informs (albeit it might sound somewhat scary indeed) you that the partial search wasn't able to find a particular extent which satisfied the criteria for partial search.

In which situations this might happen? Maybe when a file is deleted and the extent is reclaimed by the filesystem?

lorddoskias commented 2 years ago

Actually further reading the code it seems this indicates some inconsistency with the database file itself. If I provide a debug patch are you able to recompile duperemove and reproduce the issue? Also would it be possible for you to either provide your database file or parts of it (I will send you what commands to run based on the output of said debug patch)

lorddoskias commented 2 years ago

If you can apply the following diff: 

diff --git a/dbfile.c b/dbfile.c
index 1da8a86f1710..f96551993450 100644
--- a/dbfile.c
+++ b/dbfile.c
@@ -1603,6 +1603,8 @@ int dbfile_load_one_file_extent(sqlite3 *db, struct filerec *file,
        ret = sqlite3_step(stmt);
        if (ret != SQLITE_ROW) {
                perror_sqlite(ret, "retrieving extent info");
+               printf("Error finding extent, containing block: ino: %" PRIu64" loff: %" PRIu64" len: %u\n",
+                      file->inum, loff, len);
                return ret;
        }

So that it gives direct information about the culprit inode and subsequently if you could run the following sqlite commands:

sqlite3 DBFILE "SELECT poff, loff, len, flags from extents where ino = XXX" replace XXX with the inode that would be printed by the newly added debug code above and DBFILE with the name of the hash file you gave to dupremove. Then run sqlite3 DBFILE "select loff from hashes where ino = XXXX"

This shouldn't produce any sensitive output - it only gives information about the structure of the files so it would be safe to put the output here.

MichaelDietzel commented 2 years ago

Hi,

I get the same error on a 40gB win10 qcow2, so I loaded the source, applied the patch, ... The results: ./duperemove -hdr -b4k --dedupe-options=same,partial --hashfile=hashfile /mnt/vmstorage/win10.qcow2

If the changes are not backwards compatible, you will have to re-create your hash file.
Gathering file list...
Using 12 threads for file hashing phase
[1/1] (100.00%) csum: /mnt/vmstorage/win10.qcow2
Total files:  1
Total extent hashes: 3173
Loading only duplicated hashes from hashfile.
Found 1663 identical extents.
Using 6 threads to search within extents extents for additional dedupe. This process will take some time, during which Duperemove can safely be ctrl-c'd.
[%                                       ]dbfile_load_one_file_extent()/2373494: Database error 101 while retrieving extent info: no more rows available
Error finding extent, containing block: ino: 132 loff: 17323319296 len: 7483392
[########################################]
Search completed with no errors.
...

sqlite3 hashfile "SELECT poff, loff, len, flags from extents where ino = 132" > from_extents.txt 99kB, 3'173 lines

sqlite3 hashfile "select loff from hashes where ino = 132" > loff_from_hashes.txt 87MB, 7'770'443 lines

I didn't want to append the files here for size reasons, but I could provide them if needed.

Regards Michael

MichaelDietzel commented 2 years ago

Using filefrag -e I just realized that my files are also not fully deduplicated: there are some files that are both in the vm image and outside of it but not all extents are shown as shared. Also the size reduction due to deduplication was less than expected. Maybe this is related?

lorddoskias commented 2 years ago

Yes providing those files can actually help me debug the issue. Can you upload them somewhere on gdrive or some such service? Sending 87mb file for the block hashes would be too much even for email.

MichaelDietzel commented 2 years ago

By the magic of recursive compression the size got pretty mangeable - I only found out by accident and am still surprised it worked: https://drive.google.com/file/d/1UgyNazKOs3fZueRckhCTwDNczYbmPgaU/view https://drive.google.com/file/d/1nkkh7scn5VBgBjF6tboa0Q3lc_7eL6Sa/view Please let me know when you downloaded the files so i can delete them.

lorddoskias commented 2 years ago

By the magic of recursive compression the size got pretty mangeable - I only found out by accident and am still surprised it worked: https://drive.google.com/file/d/1UgyNazKOs3fZueRckhCTwDNczYbmPgaU/view https://drive.google.com/file/d/1nkkh7scn5VBgBjF6tboa0Q3lc_7eL6Sa/view Please let me know when you downloaded the files so i can delete them.

I got them you can safely delete them

lorddoskias commented 2 years ago

@MichaelDietzel so in your case duperemove is looking for an extent containing block 17323319296, looking at the extents on the other hand the closest extent which can contain this block is: 37597429760|17277128704|-1868533760|0, clearly it's unexpected that the length is a negative value. Can you provide the output of filefrag -v of the file representing ino 132. The internal representation of an extent is an uint32 and I believe it's unlikely we have a 4g extent but who knows.

MichaelDietzel commented 2 years ago

Finally back at my Computer with some time. The file has changed since I created the hashfile but I could still recreate the issue. So I took a look at filefrag and the biggest extent I found had 1'670'151 blocks of 4096 bytes so it is clearly over 4g. Having such large extents is not surprising to me, as I copied the file over from another file system to a pretty much empty xfs. Also if it gets into negative values: wouldn't uint32_t just overflow to 0 so there would need to be a signed int somewhere and also 2g already be the limit? In case you need more data I will look at a snapshot of the file next and hope that it is identical to the one I created the hashfile with. Otherwise I could also redo the hashfile and the database queries.

lorddoskias commented 2 years ago

I was able to reproduce the issue, it was actually 2 fold - we were indeed using uint32_t internally in duperemove, however the sqlite interface resorted to using int32 which further reduced the effective size to 2gb. Care to try https://github.com/markfasheh/duperemove/pull/277 it will likely solve your porblem - but you'll need to re-hash the files since the overflown values are already in your database.

MichaelDietzel commented 2 years ago

I tested the new version and it looks like the error message is gone. Thanks :-). However I am getting a lot of new? (have to verify) errors. I'll probably have to do some more tests to figure out if the errors are related to this issue or a separate issue. Still here a work in progress post, as I will have to come back to this later.

The errors I am getting (more than 1000 times for some runs): Dedupe for file "/mnt/vmstorage/win10.qcow2" had status (1) "data changed".

My current status/questions:

lorddoskias commented 2 years ago

I tested the new version and it looks like the error message is gone. Thanks :-). However I am getting a lot of new? (have to verify) errors. I'll probably have to do some more tests to figure out if the errors are related to this issue or a separate issue. Still here a work in progress post, as I will have to come back to this later.

The errors I am getting (more than 1000 times for some runs): Dedupe for file "/mnt/vmstorage/win10.qcow2" had status (1) "data changed".

This error is coming from the kernel and it basically says that the 2 extents passed for dedupe have changed so they can't be deduped.

My current status/questions:

  • Edit: my basic commandline duperemove -hdr -b4k --dedupe-options=same,partial --skip-zeroes win10.qcow2
  • The file is not opened by any other process as far as I can tell
  • when repeatedly running duperemove (no hashfile, "d" given) the number given in "Found 132439 identical extents" increases on subsequent runs
  • If I am not specifying the hashfile and also not "d", duperemove still does several hundred MB of disk writes some time close to the end. So am I really not using a hashfile?

When hashfile is not specified duperemove resorts to creating an in-memory sqlite database where all the state will be stored. However, ancillary files such as sqlite's log iteself can be stored on the /tmp filesystem.

  • The file is sparse
  • I am sometimes specifying "--skip-zeroes"

Skip zeroes basically mean to ignore extents which are unwritten and also to not csum (that is add for possible dedupe) zeroed out blocks.

  • Searching with 6 threads (The message is: "Using 6 threads to search within extents extents for additional dedupe") still only results in pretty much exactly 200% cpu load (I got 6 cores + hyper threading) (probably not related to this issue)

Unless you have explicitly set the number of threads to use duperemove will use some internal routines to try and derive the actual number of cores (excluding hyperthreads). So in this case it correctly guesses you have 6 actual cores. However, why you only see 200% I cannot comment.

MichaelDietzel commented 2 years ago

Sorry for replying that late

This error is coming from the kernel and it basically says that the 2 extents passed for dedupe have changed so they can't be deduped.

Ok, this is what I already suspected. I think this is a bug because I do not have any of the files opened at the time of running duperemove. Maybe this is the reason why I get some files that are 100% redundant only partially deduplicated? Should I open a new issue? A good guide of how to reproduce this will probably be hard... maybe I could try to generate a reasonably sized file system and send it in as a whole?

When hashfile is not specified duperemove resorts to creating an in-memory sqlite database where all the state will be stored. However, ancillary files such as sqlite's log iteself can be stored on the /tmp filesystem.

That could explain it, i'll take a closer look.

MichaelDietzel commented 2 years ago

I had to abort my test as it ran for days. See #279