nzbgetcom / nzbget

Efficient usenet downloader
https://nzbget.com
GNU General Public License v2.0
308 stars 16 forks source link

Slow download speeds and intermittent crashing due to diskstate reading errors #395

Open lars1216-nl opened 1 week ago

lars1216-nl commented 1 week ago

Is there already an issue for your problem?

NZBGet Version

v24.3-stable

Platform

Windows

Environment

Windows PC running Windows 11 pro 23H2
2.5Gbit LAN, 1Gbit fibre connection
i5 12400, 32GB RAM
Running baremetal (no docker containers or anything like that)
Saving to a stablebit drivepool setup of a bunch of mechanical HDD's with a 2 drive NVME SSD cache thats also configured with snapraid

Current Behavior

There are two issues currently.

1. Transfer speeds are very low. The highest I have seen is around the 60MB/s mark, but it usually hovers around the 12MB/s mark or even lower. Drivepool is properly flushing the NVME drives it uses as cache, so no issues there.

Considering the internet speed (1Gbit) the speed should be higher even when writing to just the mechanical drives (since SATA 3 should do around the 125MB/s mark, even if you half that in real-life use-cases then the 12MB/s speeds still wouldnt make sense).

2. NzbGet keeps crashing every 12 hours-ish with errrors in the log saying '' error reading diskstate '' followed by specific queue files. When this happens NzbGet completely stops working. Even the WebUI is eternally stuck on ''Loading, please wait''. The only ''solution'' for this is deleting all the queue files for NzbGet and then rebooting NzbGet.

Expected Behavior

1. Higher speeds, both at first and in sustained workloads.

2. No complete crashes a few times a day.

Steps To Reproduce

No response

Logs

Screenshot status nzbget

Cannot include logs since even zipped the 6GB log file is 125MB, which is too big for github unfortunately. Should be able to download them here: https://file.io/gDRoV0kw3ki3 .

Extra information

No response

dnzbk commented 1 week ago

Hi and thank you for the report.

  1. Did you play around with Write buffer? Could you try increasing(x4 maybe) it and test the disk write speed again? The server speed test doesn't write any actual data to disk, so it only measures network speed, which means the disk issues cannot be the cause of the slow speed in this case. Please make sure you are not using speed limit (the plane icon or Settings->CONNECTION->DownloadRate) and Speed Control extension. If you download something real, does NZBGet show around the same speed?

  2. I need to thoroughly investigate and understand the cause of this. Unfortunately, I couldn't open the log file you sent me because of its huge size. Could you get a new log file (a bit smaller) but using the Debug version of the app which logs additional information useful for developers? Also, consider maybe using the reset option in Settings->LOGGING->WriteLog which would delete the existing log file on program start and create a new one. It would be useful to see your nzbget.conf as well.

Are you only observing these issues only in version 24.3? Was everything fine with previous versions?

lars1216-nl commented 1 week ago

1. I did play around with the write buffer based on the things I found online during my googling to try and fix the issue on my own. it is set to 1024 based on what I found and the fact that the software itself tells me that is the recommende value for computers with enough memory, I believe it was set to 100 in the stock settings but I could be mistaken there. Should i increase this to 4096?

2. The download rate in settings is set to ''0'', which it tells me is equivelent to unlimited. I could not find the speed control extension in the settings, is this something I would have to add myself? If so, let me know how and where.

3. I observed the issues when downloading real content. Once I observed the issue I started messing around trying to fix it and used the test functionality within the settings to see if it happened there as well or was maybe related to the content I was downloading. So conclusion: yes, the same behaviour happens when downloading actual content.

3. I will try to get a new logfile for you! As for not being able to open it: I had the same issue with standard notepad, however, notepad++ had no such issues and could open the file no problem. Just a tip in the meantime. :) So far it hasnt been crashing the last 24 hours, which might be because I have decreased the amount of queue items? I had it in the multiple thousands (trying to backfill a library), I am adding at most 500 at a time now manually and it seems to atleast not crash now, but obviously this isnt a wanted behaviour. Is it a known issue that NzbGet crashes with large queues in place? The speeds are still low. I will make a new log, but for the crashing it would be useful to get into the already made log I think since its stable in that regard for now. As for the nzbget.conf , I will upload that with the new log.

4. I am not only observing this issue with 24.3. The issue was there with the previous version as well, I was just hoping it might be a known bug that was fixed in 24.3 , hence me trying that when it released yesterday.

lars1216-nl commented 1 week ago

Tried increasing the writebuffer to 4096 and did the tests again. Also downloaded the debug version of nzbget.

nzbget (2).zip

Attached is a ZIP file with new logs, the .conf file (with all usernames passwords removed, I am assuming thats okay?) and a new picture of the settings. Hopefully this, in combination with my previous comment, helps. Speeds are still low, but no crashing. As said in previous comment, I am assuming due to smaller queue based on the behaviour I am seeing, but not certain on that conclusion.

Let me know if there is anything else I can do.

dnzbk commented 1 week ago

But at the same time, speed.cloudflare or fast show the correct speed your ISP provides, right?

Thanks for the new logs and for your investigation - I'll do my best to fix these issues asap.

lars1216-nl commented 1 week ago

Those two speedtests max out around the 350 Mbps mark. However, when I use a different speedtest (https://www.speedtest.net/), it gives me fullspeed (well, close enough, around the 930-950 Mbps mark). So that may be due to the location of the servers? I use Eweka as my usenet provider, which has its servers in NL where I live, so server location should not be a problem there. But maybe cloudflare and fast dont have servers near me?

lars1216-nl commented 1 week ago

Correction: backblaze was running in the background running a backup and hogging my speed lol. Fast and cloudflare now also give me full speed (930-950 ish Mbps).

Yes, when testing NzbGet I made sure backblaze was shutdown and not interfering with speeds.

dnzbk commented 1 week ago

Thank you.

According to the screenshot you gave me, the disk speed increased by about 4 times after increasing the Write Buffer, no?

Is there any way to confirm the speed issues by testing SABNzb? SABNzb has similar tests whose results could also be useful.

Could you share that huge log file again? I'll try to open it on my more powerful laptop. Unfortunately, I deleted it, not realizing it was a one-time link. My bad.

lars1216-nl commented 1 week ago

Huge log file link again: https://file.io/bMlVFIvQKyIk .

Like I said, regular notepad just doesnt seem to like big files (tried it on my 5700X desktop, which seems plenty powerful to me). So I used notepad++ which opened it with no problems, might be worth a shot on your end as well!

As for trying SABNzb, definitely possible! Do you want me to try a disk speed test? Or should I try with actual content? Both? And when I do, just a test to see what happens or would you like logs and such too?

Disk speed increased by about 4 times in the built-in test in settings after increasing the write buffer to 4096, that is correct. However, no difference in actual download performance, still experiencing the slower speeds starting out around the 60 MB/s mark and slowing down quickly to around the 25-30 MB/s mark and eventually to around the 12MB/s mark.

dnzbk commented 1 week ago

Thank you for another link. Managed to open the logs via Vim editor.

Performing SABNzb tests and collecting results is enough. It's also worth trying real content. No need to provide SABNzb's logs.

The Write Buffer option in the disk speed tests is only used during testing, and it's used to find a reasonable value. To use the found value for real downloads, you need to go to Settings->DOWNLOAD QUEUE->WriteBuffer set it and save the settings.

lars1216-nl commented 1 week ago

Glad you were able to open the big boy log lol.

I changed the writebuffer in download queue as well already to 4096, assuming that was needed for the test as well. So that doesnt seem to be the solution for the download speed problem unfortunately.

image

Did the tests in SABNzb , seems to be working properly there. Also did threw in some content, which is downloading at the 105MB/s mark and dipping to 85MB/s at the lowest and then quickly picks back up to the 105MB/s. Still not full speed, but miles better then whats happening on NZBGet. No idea how SABNzb handles the crashing with big queues, I didnt throw in all my NZB files, just a couple for test purposes.

dnzbk commented 1 week ago

Thank you. Yes, there is something really wrong on the NZBGet side. I'll keep trying to figure out what's wrong.

lars1216-nl commented 1 week ago

Thanks! Just FYI, the webinterface is also very slow to load, takes almost half a minute. Not sure if that has anything to do with it, but might be good to know.

dnzbk commented 1 week ago

Thank you.

Please, do not use the Debug version of the app for speed testing and for other performance measures, as it works really slow. The debug version is useful for debugging crashes. Just in case.

Researched the logs (the huge ones) and gathered some statistics:

As I can see, you updated NZBGet from 21.1 to 24.3 and there were some crashes in both versions:

v21.1 crashes: 1 crash:

Mon Sep 16 20:15:39 2024        INFO    Unrar: ...         ....mkv
Mon Sep 16 20:15:39 2024        WARNING Interrupted unpack for ...
Mon Sep 16 20:15:39 2024        WARNING Direct unpack for ...failed
Mon Sep 16 20:15:39 2024        DETAIL  Flushing cache for ....part19.rar
Mon Sep 16 20:15:39 2024        DETAIL  Saved 31 articles (22.71 MB) from cache into disk for ....part19.rar
Mon Sep 16 20:15:40 2024        ERROR   Unpack for ... failed
Mon Sep 16 20:15:41 2024        INFO    nzbget 21.1 server-mode

Interrupting?

2 crash:

Mon Sep 16 20:17:06 2024        WARNING Interrupted direct unpack for ...
Mon Sep 16 20:17:08 2024        WARNING Direct unpack for ... failed
Mon Sep 16 20:17:08 2024        DETAIL  Flushing cache for ....part40.rar
Mon Sep 16 20:17:08 2024        DETAIL  Saved 111 articles (81.30 MB) from cache into disk for ....part40.rar
Mon Sep 16 20:17:08 2024        INFO    nzbget 21.1 server-mode

Interrupting?

3 crash

Tue Sep 17 17:39:02 2024        DETAIL  Downloading ....part092.rar [38/132] @ Eweka (news.eweka.nl)
Tue Sep 17 17:39:02 2024        DETAIL  Downloading ....rar [39/132] @ Eweka (news.eweka.nl)
Tue Sep 17 17:39:02 2024        DETAIL  Downloading ....rar [40/132] @ ^@^@^.
Tue Sep 17 18:47:42 2024     INFO    nzbget 21.1 server-mode

Buffer overflow for sure

4 crash

Tue Sep 17 20:38:44 2024        DETAIL  Article ....rar [61/68] @ Eweka (news.eweka.nl) failed, could not fetch article: 430 No Such Article
Tue Sep 17 20:38:44 2024        DETAIL  Download ....part66.rar [61/68] cancelled
Tue Sep 17 20:38:44 2024        DETAIL  Flushing cache for ....part65.rar
Tue Sep 17 20:38:44 2024        DETAIL  Saved 66 articles (48.34 MB) from cache into disk for ....part65.rar
Tue Sep 17 20:38:44 2024        DETAIL  Flushing cache for ...b.part66.rar
Tue Sep 17 20:38:44 2024        DETAIL  Saved 28 articles (20.51 MB) from cache into disk for ....part66.rar
Tue Sep 17 20:38:45 2024        INFO    nzbget 21.1 server-mode

Failed article?

5 crash

Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part015.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part016.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part017.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part018.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part019.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part02.rar from download queue
Wed Sep 18 08:59:52 2024        DETAIL  Deleting file ....part020.rar from download queue
Wed Sep 18 09:00:03 2024        INFO    nzbget 21.1 server-mode

Deleting lots of files? And looks like the update to v24.3 was happening here and after that, the ERROR Error reading diskstate errors appeared

Wed Sep 18 09:05:12 2024 ERROR Error reading diskstate: could not open file D:\Torrents\queue\163056: No such file or directory
Wed Sep 18 09:05:12 2024 ERROR Error reading diskstate: could not open file D:\Torrents\queue\163057: No such file or directory
Wed Sep 18 09:05:12 2024 ERROR Error reading diskstate: could not open file D:\Torrents\queue\163048: No such file or directory

v24.3 crashes: 1 crash

Wed Sep 18 09:25:46 2024        INFO    Reloading...
Wed Sep 18 09:25:46 2024        WARNING Cancelling direct unpack for ...
Wed Sep 18 09:25:46 2024        WARNING Interrupted direct unpack for ...
Wed Sep 18 09:25:46 2024        WARNING Direct unpack for ...
Wed Sep 18 09:25:46 2024        DETAIL  Download ....part16.rar [65/68] cancelled

Interrupting?

2 crash

Wed Sep 18 09:34:18 2024        WARNING Interrupted direct unpack for ...
Wed Sep 18 09:34:18 2024        INFO    Successfully downloaded ....part057.rar
Wed Sep 18 09:34:19 2024        DETAIL  Flushing cache for ....part058.rar
Wed Sep 18 09:34:19 2024        DETAIL  Saved 30 articles (21.97 MB) from cache into disk for ....part058.rar
Wed Sep 18 09:34:20 2024        WARNING Direct unpack for ... failed
Wed Sep 18 09:34:21 2024        INFO    nzbget 24.3 server-mode

Interrupting?

3 crash

Wed Sep 18 09:34:52 2024        INFO    Unrar: Extracting from ....part006.rar
Wed Sep 18 09:34:52 2024        WARNING Cancelling direct unpack for ...
Wed Sep 18 09:34:53 2024        WARNING Interrupted direct unpack for ...
Wed Sep 18 09:34:53 2024        DETAIL  Download ....part059.rar [118/137] cancelled
Wed Sep 18 09:34:53 2024        DETAIL  Download ....part059.rar [119/137] cancelled
Wed Sep 18 09:34:54 2024        DETAIL  Flushing cache for ....part059.rar
Wed Sep 18 09:34:54 2024        WARNING Direct unpack for ... failed
Wed Sep 18 09:34:54 2024        DETAIL  Saved 22 articles (16.11 MB) from cache into disk for ....part059.rar
Wed Sep 18 09:35:00 2024        INFO    nzbget 24.3 server-mode

Interrupting?

4 crash

Wed Sep 18 10:27:31 2024        WARNING 7 of 137 article downloads failed for ....part375.rar"
Wed Sep 18 10:27:31 2024        DETAIL  Detected non-par2-file ....part01.rar
Wed Sep 18 10:27:31 2024        ERROR   Unhandled Exception: code: 0xC0000005, flags: 0, address: 0x7DC0D170
Wed Sep 18 10:27:31 2024        INFO    Detailed crash information can be printed by debug version of NZBGet. For more info visit https://nzbget.com/documentation/crash-dump/
Wed Sep 18 10:29:20 2024        INFO    nzbget 24.3 server-mode
^[OA^[OA^[OA^[OA^[OA^[OAWed Sep 18 10:29:20 2024        
INFO    using C:\ProgramData\NZBGet\nzbget.conf
Wed Sep 18 10:29:20 2024        INFO    nzbget runs on 0.0.0.0:6789

Failed articles?

5 crash

Wed Sep 18 09:35:31 2024        WARNING Cancelling direct unpack for ...
Wed Sep 18 09:35:31 2024        INFO    Collection ... added to queue
Wed Sep 18 09:35:32 2024        DETAIL  Saved 51 articles (37.35 MB) from cache into disk for ....part062.rar
Wed Sep 18 09:35:32 2024        WARNING Interrupted direct unpack for ...
Wed Sep 18 09:35:33 2024        WARNING Direct unpack for ... failed
Wed Sep 18 09:35:34 2024        INFO    nzbget 24.3 server-mode

Interrupting?

6 crash

Wed Sep 18 10:27:31 2024        WARNING 7 of 137 article downloads failed for ....part375.rar"
Wed Sep 18 10:27:31 2024        DETAIL  Detected non-par2-file ....part01.rar
Wed Sep 18 10:27:31 2024        ERROR   Unhandled Exception: code: 0xC0000005, flags: 0, address: 0x7DC0D170
Wed Sep 18 10:27:31 2024        INFO    Detailed crash information can be printed by debug version of NZBGet. For more info visit https://nzbget.com/documentation/crash-dump/
Wed Sep 18 10:29:20 2024        INFO    nzbget 24.3 server-mode

Faield articles?

7 crash

Wed Sep 18 17:20:20 2024        WARNING Interrupted unpack for ...
Wed Sep 18 17:20:20 2024        DETAIL  Flushing cache for ....part36.rar
Wed Sep 18 17:20:20 2024        DETAIL  Download ....part041.rar [1/68] cancelled
Wed Sep 18 17:20:20 2024        DETAIL  Saved 1 articles (0.73 MB) from cache into disk for ....part36.rar
Wed Sep 18 17:20:20 2024        DETAIL  Flushing cache for ....part37.rar
Wed Sep 18 17:20:20 2024        DETAIL  Download ....part039.rar [1/68] cancelled
Wed Sep 18 17:20:20 2024        DETAIL  Saved 1 articles (0.73 MB) from cache into disk for ....part37.rar
Wed Sep 18 17:20:20 2024        DETAIL  Flushing cache for ....part38.rar
Wed Sep 18 17:20:20 2024        DETAIL  Saved 1 articles (0.73 MB) from cache into disk for ....part38.rar
Wed Sep 18 17:20:21 2024        ERROR   Unpack for ... failed
Wed Sep 18 17:20:22 2024        INFO    nzbget 24.3 server-mode

Interrupting?

1) ERROR Error reading diskstate: could not open file errors happened after/during update. 2) Something causes the unpacking to abort and then the app crashes. 3) Failed articles can lead to crash. 4) Buffer overflow was found in one place, which caused a crash.

I'll try to reproduce and fix them.

No luck with speed issues so far. Just maybe, please try to play with the number of connections (start with 8 and double it each time) to see the differences. I see you are using 50 connections, which is the maximum for eweka, but still.

I recently fixed an issue with incorrect speed display if the download speed is faster than 2Gb/s and a guy, who raised this topic on Reddit, was happy about it, so it looks really weird to me.

lars1216-nl commented 1 week ago

1. Dont use debug in production, that made sense to me. So I already re-installed the regular version for the speed testing afterwards. If you need debug version logs again please let me know cause I will have to reinstall the debug version again.

2. Yeah, I went from 21.1 to 24.3 for two reasons. One, I found out it was a fork that was still being updated, I had the old NzbGet which i didnt realise , and two, I was hoping it might fix the issues I was having.

3. I did manually delete a bunch of queue files through file explorer, did it either two or three times actually, cause that seemed to fix the whole crashing issue. Possibly corrupt queue files? Just a thought. Although, now that i think about it, if it shows up in the logs it cant be by manual deletion but must be deletion by NzbGet itself?

4. I will try to play around with the number of connections. It seemed logical to use the max allowed by the usenet provider, but maybe it isnt? This is my first time using usenet. I will try your suggestion and report back on that.

5. I do not think its an incorrect speed display in NzbGet in this case personally. Cause if it was, and it was actually going at full speed, then network usage should show full usage. And it isnt. Both task manager and my router config show usage matching what NzbGet is showing me.

dnzbk commented 1 week ago
  1. Might be. I will debug that too.
  2. Thank you.
  3. I've just meant that NZBGet can easily utilize even such big network channels, so it's look strange to me why it doesn't work in your case.
lars1216-nl commented 1 week ago

Reporting back:

Played around with the number of connections. Lowering it did lower the transfer speed (maxing out around 10MB/s with 8 connections and around 22MB/s with 16 connections), with 32 connections I was back to my max of around 50MB/s as before and bumping it up from there did nothing.

On all amounts of connections it dipped back down again like before, except on 8 connections when it was stable around the 10MB/s mark. So on 8 connections it was stable low, on higher amounts of connections the fluctuation was the same as before.

dnzbk commented 1 week ago

Yeah, that was predictable. Thank you.

lars1216-nl commented 4 days ago

Just FYI, just loaded up the queue again with almost 1000 items. So we can see whether or not NzbGet really does crash with a large queue, since its been stable (apart from the speeds) the last few days with a smaller queue. I will report back on the results.