Program health seems to worsen with high load

[colemar]

Windows XP SP2 running on a Pentium 4 2.40 GHz with 1.5 GB RAM.

I have configured 2 main servers with 5 connections each and 2 backup server again with 5 connections each; the backup servers are tipically not used.  The average download speed is around 2500 KBytes/s and the CPU usage is between 75% and 100%.

Using Proxifier to reroute the NNTP traffic through a corporate HTTPS proxy, as explained in another thread.

My typical way to use SAB is to let it run over the night.
Last night I let it run with a big queue that amounts to 270 GBytes (with 256 GB as a single nzb file). Estimated time of completion was about 26 hours as reported by the web interface.

This morning, after 8 hours, I found that SAB did download only about 28 GB instead of the 70 GB I was expecting.
May be there was a network congestion, but some things make me believe that something bad happened to SAB.

Symptoms:

Since I configured 200 MB as article cache, typical RAM usage (Mem Usage and VM Size as reported by Task Manager) has been around 200 MB or a little more.  This morning SAB RAM usage is reported at about 1.1 GB!

As seen in log file, SAB started at 23:45 (at that time the queue was only about 14 GB, some minutes later I added another 256 GB as a single nzb file)

Code: Select all

2009-02-03 23:45:10,671::INFO::--------------------------------
2009-02-03 23:45:10,687::INFO::SABnzbd.exe-0.4.6 (rev=1888)
2009-02-03 23:45:10,687::INFO::Platform=Windows-XP-5.1.2600-SP2 Class=nt
2009-02-03 23:45:10,687::INFO::Python-version = 2.5.2 (r252:60911, Mar 27 2008, 17:57:18) [MSC v.1310 32 bit (Intel)]
2009-02-03 23:45:10,687::INFO::[sabnzbd] Loading data for rss_data.sab from C:\Program Files\SABnzbd\cache\rss_data.sab
2009-02-03 23:45:10,703::INFO::[sabnzbd] Loading data for bytes7.sab from C:\Program Files\SABnzbd\cache\bytes7.sab
2009-02-03 23:45:10,703::INFO::[sabnzbd] Loading data for queue7.sab from C:\Program Files\SABnzbd\cache\queue7.sab
2009-02-03 23:45:10,703::INFO::[sabnzbd] Loading data for SABnzbd_nzo_kh6k-0 from C:\Program Files\SABnzbd\cache\SABnzbd_nzo_kh6k-0
2009-02-03 23:45:17,842::INFO::[sabnzbd] Loading data for SABnzbd_nzo_jm3ksw from C:\Program Files\SABnzbd\cache\SABnzbd_nzo_jm3ksw
2009-02-03 23:45:17,875::INFO::[sabnzbd] Loading data for SABnzbd_nzo_sh94wn from C:\Program Files\SABnzbd\cache\SABnzbd_nzo_sh94wn
2009-02-03 23:45:17,953::INFO::[sabnzbd] Loading data for watched_data.sab from C:\Program Files\SABnzbd\cache\watched_data.sab
2009-02-03 23:45:17,953::INFO::All processes started

now the time is 09:05 and the current log file is stuck at 00:02, the last line is as follows

Code: Select all

2009-02-04 00:02:38,155::INFO::[articlecache] Added <Article: article=part33of59.5ytgIC1dNwojnrbtv&[email protected], bytes=258652, partnum=33, art_id=None> to cache

The current log file size is 5242875 bytes that is about the same size as the older log files, so I believe a log rotation should have been happened at 00:02, but it did not happen. No disk is full yet.

I paused the queue then waited to see the connections drop to zero.

Unlocker is an utility that lets me know what processes own handles for a given file. It reports that par2.exe (which seems to be running happily at 94-97% CPU) is locking  the current log file!!?!?! I was expecting SABnzbd.exe here.
Another utility (Handle v2.01 by Sysinternals) confirms that par2.exe owns a handle for logs\sabnzbd.log while SABnzbd.exe has none. It reports that par2.exe owns a handle for cache\queue7.sab (!?!?!?!)

Now that par2.exe is done no handles are reported for logs\sabnzbd.log (still stuck at 00:02) and SABnzbd.exe has suddenly gone up to 97% CPU (perhaps it is unpacking and deleting files).
5 minutes later SABnzbd.exe CPU usage drops to about 35% and then to 0% when another par2.exe is launched. This time par2.exe has no handles for  logs\sabnzbd.log (still stuck at 00:02).

Task Manager reports  the following for SABnzbd.exe:
Mem Usage: 998772 K
Peak Mem Usage: 1298968 K
Handles: 200
Threads: 20
I/O Reads: 518082 (not growing for now)
I/O Writes: 1697478 (growing)

Now the History page reports that all the processing is done and the CPU usage is very low, but the memory usage is about the same as before.

I'll try to keep SAB running and paused in the hope to have some suggestions to further analyze the situation.

[shypike]

I don't recognize this behaviour.
It is true that use of the web-ui isn't always a pleasure when a relatively slow
system is very busy.
I do think that your process tools are inaccurate.
par2 runs as child process of SABnzbd, so I think that unlocker mixes things up.
Try the SysInternals process tool instead.
par2 does not use the logfiles and the .sab files, it doesn't even know they exist.

I cannot explain the high memory usage.
If you set a limit for the article cache, memory growth should be limited.
Unless you discovered a memory leak of course.

BTW: do not underestimate what verification (and especially repair) of a 256GB
job costs in resources. I'm not sure how well par2 copes with this.


I have no idea what the influence of Proxifier is.

[colemar]

Sysinternals Process Explorer v11.21 shows a list of file handles for the process SABnzbd.exe, and there are no handles for the log file!
As a confirmation, it reports a file handle for a rar file owned by the running par2.exe.

Somehow SABnzbd lost the access to the log file about 17 minutes after its start. Maybe the import of a nzb file listing 256 GB of articles was too much to flush to the log file and log file management has broken.
In fact I have found no traces of that import in the log file set.

High memory usage may have been triggered by the very same event that broke log management, or may be the result of processing the nzb file without releasing memory after.

If you are interested I can send the nzb file (15 MB after being gzipped by SAB).

[switch]

Code: Select all

Last night I let it run with a big queue that amounts to 270 GBytes (with 256 GB as a single nzb file).

Why would you have a single nzb file listing 256GB of content? You really should be splitting it down and having a single nzb for each rar set. That is what sabnzbd is programmed for.

There is a current leak of memory for the built in python xml parser we use, cElementTree. The parser does not give back memory used when parsing an nzb file, this is usually not too noticable unless you are dealing with very large nzb files. I wouldn't have thought it would reach to 1.1GB leak however.

For 0.5 we have changed to a different parsing solution which will both reduce memory usage during parsing, and give us all the memory back

An example of cElementTree not giving back RAM

What it should be like (time scale is different, just focus on ram levels going back to what it was before):

[colemar]

Why would you have a single nzb file listing 256GB of content? You really should be splitting it down and having a single nzb for each rar set. That is what sabnzbd is programmed for.

The nzb file is listing 6 rar sets all related to a single TV series.
It was generated using newzleech.com search engine and the reason for a single file is both that I like to keep related downloads together and that some search engines aggressively try to aggregate related postings.

I agree that cElementTree is very likely the culprit for the high memory usage, but there may be some other factor responsible for the unexplicable logging stop.

Anyway thanks for the suggestion, I will try to keep nzb files down to a reasonable size.

[shypike]

The logging stop is a known Python issue.
In the sense that the authors do not acknowledge it, but
many people complain about it.
I very much doubt if par2.exe has anything to do with it.

Is it possible to upload the NZB file to, say http://drop.io ?
Or email the newzleech search term to [email protected].

[colemar]

I uploaded the file then sent the link to [email protected].

I doubt that the file is still relevant because the last night I submitted to SABnzbd another file whose size is only 1/6 of the file in question (available at drop.io) , and the logging stop happened again. The log stopped at 2009-02-04 22:51:04,405 (about 9 hours ago).

[shypike]

The logging doesn't worry me.
When happens on my system, the downloading and post-processing happily continue.
I want to get a grip on the memory usage.

[reem01]

Yeah, I have the same issue with memory usage.  Leaving sabnzbd running with firefox it just eats memory.  After a day or two it will be close or over 1 GB of memory usage.  It won't even shut firefox down, have to end the task.  So when that gets figured out I will be very happy.  This is a great little software app, many thanks for the developers!