Sabnzbd takes twice the time than reported (and expected)

[isofan]

Hi,

I have a huge problem with Sabnzbd 0.6.9, which I simply cannot solve. I run sabnzbd as a service on my Windows Homeserver (WHS). For example, I start a download at 0:00h, which is expected to take 3 hours. After the download is finished, sabnzbd reports that the download has taken 3 hours, the transfer rate fits that perfectly, but in reality, twice the time has passed, i.e. the next download is started at 6:00h.

These are simple figures, but I have made a screenshot illustrating this, look at the finished-times and the absolute times. What is going terribly wrong there? Is Sabnzbd downloading the files twice? I have already observed taskmanager, but it displays only one Sabnzbd process.

This happens mainly at night, when I am not monitoring my computer. So my first guess was that the transfer rate drops, but the transfer rate reported fits the time required. Maybe a loss in connection at all? Would Sabnzbd report that? I have no errors or warnings, and my DSL router does not report any errors or connection losses at all.



Any ideas what is going on? Where does that huge time difference come from? I am totally lost, any help appreciated. Thanks alot.

[sander]

A thing to consider: the *downloading* is only one phase; after that the unrarring/parring (repair + unpack) takes places, and then the script stuff (if any).

So if you have a slow CPU / slow system, or you're writing to a slow drive / network-drive, that can take considerable time.

FWIW: on my mediaplayer the repair/unpack takes much longer than the download.

So, could this be the cause?

[isofan]

Hi sander,

this is a pretty fast core i3 machine, unpacking only takes a few minutes with these small packages, the tooltip above the repair- and unpack-icons say about 1 to 2 minutes for each of the downloads. Besides, my machine starts a new download while unpacking is in progress.

This problem is really driving me nuts, especially because the logging/debugging contains tons of information, none of which is really useful to reproduce what's really happening there. My guess would be that the files are downloaded twice, but I cannot find anything to prove or disprove this assumption.

Is there any suitable way to solve this problem? This must be some major issue, don't you think?

One more thing that has come to my mind: what if the DL-speed drops to 0 KB/s, like for example when the user presses pause, or the internet connection is unavailable? Will this be calculated in the average download rate as well? Unfortunately sabnzbd offers no possibility to monitor the download speed in a certain time interval, I'd wish there would be some statistics like: from 00:00h to 01:00h: transferred x.y MB or so.

[sander]

Hi,

SABnzbd does log its downloadspeed all the down: see the lines with 'bps' in your sabnzbd.log file. And see the example below.

Furthermore, SAB logs what it is doing when. So "grep" your logfile on a certain download and 'bps'.
A quicker way to get an overview, is clicking on the name in the History: you will get an idea what SAB is doing when. See my example below

Code: Select all

sander@R540:~/.sabnzbd/logs$ grep -i bps sabnzbd.log | head
2011-10-09 20:44:22,572::DEBUG::[bpsmeter:179] bps: 3330705.6359
2011-10-09 20:44:27,573::DEBUG::[bpsmeter:179] bps: 3609147.51575
2011-10-09 20:44:32,573::DEBUG::[bpsmeter:179] bps: 3714277.0215
2011-10-09 20:44:37,573::DEBUG::[bpsmeter:179] bps: 3592009.07302
2011-10-09 20:44:42,573::DEBUG::[bpsmeter:179] bps: 3643225.44453
2011-10-09 20:44:47,574::DEBUG::[bpsmeter:179] bps: 3723103.07333
2011-10-09 20:44:52,574::DEBUG::[bpsmeter:179] bps: 3700450.10479
2011-10-09 20:44:57,574::DEBUG::[bpsmeter:179] bps: 3785805.53469
2011-10-09 20:45:02,574::DEBUG::[bpsmeter:179] bps: 3551341.42011
2011-10-09 20:45:07,575::DEBUG::[bpsmeter:179] bps: 3473542.19454

sander@R540:~/.sabnzbd/logs$ grep -i unrar sabnzbd.log |  grep -vi binary | head

2011-10-09 20:50:57,913::INFO::[newsunpack:196] Unrar starting on /home/sander/Downloads/incomplete/das weib - info
2011-10-09 20:50:57,942::DEBUG::[newsunpack:530] Running unrar ['/usr/bin/unrar', 'x', '-idp', '-o-', '-or', '-p-', '/home/sander/Downloads/incomplete/das weib - info/info-das weib (1981).part001.rar', '/home/sander/Downloads/complete/_UNPACK_das weib - info/']
2011-10-09 20:54:07,869::INFO::[newsunpack:200] Unrar finished on /home/sander/Downloads/incomplete/das weib - info
2011-10-12 19:09:32,610::INFO::[newsunpack:189] Unrar starting on /home/sander/Downloads/incomplete/Boris.S06E02.Once.Upon.a.Time.HDTV.XviD-FQM
2011-10-12 19:09:32,614::DEBUG::[newsunpack:518] Running unrar ['/usr/bin/unrar', 'x', '-idp', '-o-', '-or', '-p-', '/home/sander/Downloads/incomplete/Boris.S06E02.Once.Upon.a.Time.HDTV.XviD-FQM/Boris.S06E02.Once.Upon.a.Time.HDTV.XviD-FQM.part01.rar', '/home/sander/Downloads/complete/_UNPACK_Boris.S06E02.Once.Upon.a.Time.HDTV.XviD-FQM/']
2011-10-12 19:09:44,518::INFO::[newsunpack:193] Unrar finished on /home/sander/Downloads/incomplete/Boris.S06E02.Once.Upon.a.Time.HDTV.XviD-FQM

sander@R540:~/.sabnzbd/logs$ 

Example

Completed 2011-10-11 21:38:50
Name Oh Oh Hero - S02E04
Size 465 MB
Status Completed
Category a.b.nl
Path /home/sander/Downloads/complete/Oh Oh Hero - S02E04
Download Downloaded in 2 minutes 24 seconds at an average of 3.2 MB/s
Repair [Oh Oh Hero - S02E04] No par2 sets

[sander]

Here is an one-liner to see all the details of a certain download: you can see the time actions start and finish, and the download speed.

With this kind of analysis you should be able to determine what's going at night.

Code: Select all

sander@R540:~/.sabnzbd/logs$ grep -i -e ubuntu -e bps sabnzbd.log  | grep -i -e creating  -e "par2 check" -e unrar -e bps | grep -A 100000 -i creating | head -10
2011-10-13 19:10:24,870::INFO::[misc:719] Creating directories: /home/sander/Downloads/incomplete/ubuntu-11.10-beta1-alternate-amd64
2011-10-13 19:10:32,031::DEBUG::[bpsmeter:179] bps: 1761630.69802
2011-10-13 19:10:37,032::DEBUG::[bpsmeter:179] bps: 1876109.54833
2011-10-13 19:10:42,034::DEBUG::[bpsmeter:179] bps: 1944898.02358
2011-10-13 19:10:47,035::DEBUG::[bpsmeter:179] bps: 1958259.40733
2011-10-13 19:10:52,036::DEBUG::[bpsmeter:179] bps: 1987261.22982
2011-10-13 19:10:57,036::DEBUG::[bpsmeter:179] bps: 1348147.73902
2011-10-13 19:11:02,041::DEBUG::[bpsmeter:179] bps: 1724410.81676
2011-10-13 19:11:07,041::DEBUG::[bpsmeter:179] bps: 1853860.46698
2011-10-13 19:11:12,048::DEBUG::[bpsmeter:179] bps: 1951487.03687

sander@R540:~/.sabnzbd/logs$ 
sander@R540:~/.sabnzbd/logs$ grep -i -e ubuntu -e bps sabnzbd.log  | grep -i -e creating  -e "par2 check" -e unrar -e bps | grep -A 100000 -i creating | tail -20
2011-10-13 19:17:03,610::DEBUG::[bpsmeter:179] bps: 965498.264333
2011-10-13 19:17:08,672::DEBUG::[bpsmeter:179] bps: 401966.412202
2011-10-13 19:17:14,070::DEBUG::[bpsmeter:179] bps: 206097.062698
2011-10-13 19:17:19,232::DEBUG::[bpsmeter:179] bps: 102239.514421
2011-10-13 19:17:24,239::DEBUG::[bpsmeter:179] bps: 41038.3806482
2011-10-13 19:17:29,246::DEBUG::[bpsmeter:179] bps: 16473.9790543
2011-10-13 19:17:34,722::DEBUG::[bpsmeter:179] bps: 7032.6290383
2011-10-13 19:17:39,729::DEBUG::[bpsmeter:179] bps: 2822.92804856
2011-10-13 19:17:44,736::DEBUG::[bpsmeter:179] bps: 1133.16222463
2011-10-13 19:17:49,742::DEBUG::[bpsmeter:179] bps: 454.913490577
2011-10-13 19:17:54,749::DEBUG::[bpsmeter:179] bps: 182.611352321
2011-10-13 19:17:59,755::DEBUG::[bpsmeter:179] bps: 73.3106436504
2011-10-13 19:18:05,448::DEBUG::[bpsmeter:179] bps: 105498.650122
2011-10-13 19:18:10,475::DEBUG::[bpsmeter:179] bps: 243864.600859
2011-10-13 19:18:13,838::INFO::[postproc:498] Par2 check starting on ubuntu-11.10-beta1-alternate-amd64
2011-10-13 19:18:13,861::INFO::[postproc:527] Par2 check finished on ubuntu-11.10-beta1-alternate-amd64
2011-10-13 19:18:13,861::INFO::[misc:719] Creating directories: /home/sander/Downloads/complete/ubuntu-11.10-beta1-alternate-amd64
2011-10-13 19:18:13,900::INFO::[newsunpack:196] Unrar starting on /home/sander/Downloads/incomplete/ubuntu-11.10-beta1-alternate-amd64
2011-10-13 19:18:13,913::DEBUG::[newsunpack:530] Running unrar ['/usr/bin/unrar', 'x', '-idp', '-o-', '-or', '-p-', '/home/sander/Downloads/incomplete/ubuntu-11.10-beta1-alternate-amd64/ubuntu-11.10-beta1-alternate-amd64.part01.rar', '/home/sander/Downloads/complete/_UNPACK_ubuntu-11.10-beta1-alternate-amd64/']
2011-10-13 19:19:04,857::INFO::[newsunpack:200] Unrar finished on /home/sander/Downloads/incomplete/ubuntu-11.10-beta1-alternate-amd64

sander@R540:~/.sabnzbd/logs$

and the GUI output from SAB:

Completed 2011-10-13 19:19:04
Name ubuntu-11.10-beta1-alternate-amd64
Size 701 MB
Status Completed
Category a.b.boneless
Path /home/sander/Downloads/complete/ubuntu-11.10-beta1-alternate-amd64
Download Downloaded in 6 minutes 30 seconds at an average of 1.8 MB/s
Repair [ubuntu-11.10-beta1-alternate-amd64] Quick Check OK
Unpack [ubuntu-11.10-beta1-alternate-amd64] Unpacked 1 files/folders in 50 seconds

[isofan]

Hi sander,

thanks alot, but this output from the debug log gives me exactly the same data as I showed in my first screenshot, it's only a more comfortable way than reading the screenshots from the GUI. According to this data, everything is fine, except for the time lost between the downloads.

My theory is that some time in the night the connection to my Usenet provider may get lost. Question: will Sabnzbd report this? Is there a way to determine the amount of data transferred in a specified time, say from 2:00h to 3:00h?

My internet connection is fine, my router logs any faulty internet connection, but it won't be able to log losses to the usenet provider, so how can I see if this happens? Any way in Sabnzbd?

Is there any way to make a dump of the current download action for example every 10 minutes?

The problem persists, and I still have no clue why. It never happens when I am working on any computer in my network, but only when I'm away

I tried wget (under windows), but it won't grab the sabnzbd status page successfully since it uses java script, the mobile version doesn't work either. Is it possible to have sabnzbd create a static site, which I could WGET peridically to see what happens?

[sander]

Yes, SABnzbd continuously reports the speed: see my post http://forums.sabnzbd.org/viewtopic.php ... 407#p56051

So: check your sabnzbd.log for 'bps'. You can put it into a spreadsheet to get totals and graphs.

HTH

[isofan]

Hi,

okay, I am still investigating this issue, and I am thankful for your help. I have pasted a logfile for one particular download, so the amount of data is quite manageable, have a look here:

http://pastebin.com/1VXpddvy

First of all, Sabnzbd reports that this download of "File001.placeholder" finished after 1 hour, 11 minutes and 30 seconds, has a size of 745MB at a rate of 178kB/s. This is what I would expect from my slow connection, and I would be satisfied if this was true.

Howver, the download started at 8:45h, and the following download was initiated at 11:06h, making a total of 2 hours, 26 minutes, more than twice the time.

When I look at the log, I cannot clearly identidfy where that time really gets lost. Can you gelp me interprete that data?

P.S. I have switched of the debug for this download, so no BPSMeter, but believe me that BPSMeter shows values approximately around the mentioned 178KB/s stated above, which are not reached if you really sum it up. My new theory is that the speed is correct, but Sabnzbd pauses the download after each file or so, and does something else. But what?

[isofan]

Hi,

after all, I am still having this issue, does nobody have any clue what might be wrong with my config?

[shypike]

Post-processing can take a lot of time especially on slower systems
and when par2 repair is needed.
When you have enabled the option to halt download during post-processing,
It would explain things.

[isofan]

Hi,

extracting is very fast on my system, for example it takes only 2 minutes to extract 4GB of RAR archives. And the option to halt download during post processing is not enabled.

is it possible that something goes terribly slow when the watched folder, which is located on a server drive, is inaccessible? Because everytime I watch the downloads on my computer where the watch folder is located, I do not get the slowdowns, but however when this machine is off, the issue appears again. Just a thought, but why should the two things be related?

Anyway, the details logged are not sufficient to solve this

[shypike]

is it possible that something goes terribly slow when the watched folder, which is located on a server drive, is inaccessible? Because everytime I watch the downloads on my computer where the watch folder is located, I do not get the slowdowns, but however when this machine is off, the issue appears again.(

Possibly, hard to tell. It depends very much on what the OS does.
SABnzbd uses separate threads for independent tasks.
On the other hand what you describe it not situation that I test normally.
Obviously since you say it's repeatable, there must be some connection,
but it's not clear to me how SABnzbd could be fixed to avoid it.
Is there anything else on the server that SABnzbd would need?