All,

Is anyone else seeing problems with QRecall after applying the 10.5.6 update from Apple?

I've got an action that backs up my entire hard drive ever three days, so I didn't notice this until this morning when I got up and my machine was hung with just 7 MB of RAM free. I've narrowed this down to QRecall. It seems that as the action runs, my Free RAM drops in proportion to the progress of the backup job till QRecall itself hangs and the machine is left in an unusable state.

The archive in question is about 39.2GB. I've been able to successfully do a verify on the archive without any issues with memory usage. Only during a capture does this memory usage become an issue.

My machine is a MacbookPro with 3 GB of RAM installed. All of this was working perfectly for a few months (since I purchased QRecall) and seems too much of a coincidence with the application of the 10.5.6 update to dismiss.

I don't see anything in the Console logs when this occurs, nor anything in the QRecall logs.

What else can I look for here or any other information I can provide to help troubleshoot this?

Thanks,

Steve

EDIT: Note that the Inactive memory grows in proportion to the Free memory decrease. Almost like a memory leak of some sort.

Hello Steve,

Please send a diagnostic report. It probably won't explain what's happening, but it will give me your system configuration.

I haven't seen anything out of the ordinary here, but that's not to say that the 10.5.6 update isn't causing problems. Memory issues can manifest themselves quite differently on different computers. The same bug on one system might not cause any noticeable effects while bringing another system to its knees.

The overall system memory measurements (wired, active, inactive, free) aren't that helpful as these labels are both vague and memory gets used for so many purposes. It's difficult use these numbers to pinpoint a cause. For example, I would always expect your free memory to creep towards zero as a capture progresses. The operating system uses any free memory to cache file and directory blocks, so the act of reading a bunch of files will naturally consume all of your free RAM. But that RAM really isn't "used" because the system will give it back immediately to any application that wants it. So some of your "used" memory is really used while other "used" memory isn't. Confusing, huh?

What I would be interested in knowing is if the virtual memory size of the QRecallHelper process grows continuously and if your system is swapping excessively during a capture. Both of these can be observed in the Activity Monitor application. Once the capture is underway, the QRecallHelper process should have a virtual memory address space around the size of you physical RAM (up to 2GB). That size should remain fairly stable, increasing or decreasing only by a few hundred megabytes, until the capture is finished. On the other hand, if the virtual memory size continually increases it will start to cause excessive swapping with the virtual memory store. This will cause your system to run very slowly, the QRecallHelper process could crash, or it could eventually cripple the OS.

If you see any of this kind of behavior, I'll see if I can reproduce the problem here and find out what's causing it.

James,

I've uploaded a diagnostic report.

What you mention in your last paragraph appears to be what is happening on my machine. I've seen the virtual memory up to 5.7GB when this happens and I've rebooted the machine. I'll keep Activity Monitor running and see if I can get you some more numbers.

Thanks,

Steve

More info. I'm backing up to a Netgear ReadyNAS Duo (been working great for this) and when the QRecallHelper process seems to hang, after a while I get the following in the NAS debug logs:


Dec 18 15:49:03 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49196/548 shrinks window 2485101120:2485129584. Repaired.
Dec 18 15:51:03 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49196/548 shrinks window 2485101120:2485129584. Repaired.
Dec 18 15:53:03 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49196/548 shrinks window 2485101120:2485129584. Repaired.
Dec 18 15:55:03 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49196/548 shrinks window 2485101120:2485129584. Repaired.
Dec 18 15:57:03 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49196/548 shrinks window 2485101120:2485129584. Repaired.
Dec 18 19:00:23 nas1 kernel: TCP: Treason uncloaked! Peer 192.168.25.80:49182/548 shrinks window 2641438214:2641466678. Repaired.

Wonder if Apple did something with the window scaling in 10.5.6???

At this point, I have 56M of Free RAM, 1.47GB of inactive RAM, QRecall is in a (Not Respoding) state in Activity Monitor. QRecallHelper is showing 455.92MB of Real memory and 1.64GB of virtual memory.

Thanks,

Steve

Steve Mayer wrote:What you mention in your last paragraph appears to be what is happening on my machine. I've seen the virtual memory up to 5.7GB when this happens and I've rebooted the machine.

You have 4GB of physical RAM, so a 5.7GB VM size isn't that much. As a counter example, I have 4.5GB of physical RAM and I'm currently running with a VM size of 68GB with no problem. The more interesting numbers are the Swap used and Page in/out counts.

More info. I'm backing up to a Netgear ReadyNAS Duo (been working great for this) and when the QRecallHelper process seems to hang, after a while I get the following in the NAS debug logs:

That's interesting, but I don't know what that means. You'll probably need to contact Netgear for an explanation.

At this point, I have 56M of Free RAM, 1.47GB of inactive RAM,

Looks normal.

QRecall is in a (Not Respoding) state in Activity Monitor.

That's odd. If this happens again, capture a sample of the QRecall application (Activity Monitor, select the QRecall application process, choose Sample Process, then save the output to a text file) and send it to me.

QRecallHelper is showing 455.92MB of Real memory and 1.64GB of virtual memory.

Those look like perfectly reasonable values.

One way of isolating the problem would be to capture a comparable amount of data to a new archive on a local volume. If the same thing happens, then the problem could be an interaction between QRecall and OS X 10.5.6. If it doesn't happen, then it could be a problem or memory leak with the NAS volume drivers.

Okay, so I tried my full back up on my PPC iMac. This archive is about 2/3 the size of the one from the Macbook and it succeeded (saving to the same NAS).

I had some tweaks in place on the Macbook in the /etc/sysctl.conf file. I've removed them for now and am going to attempt another shot at the backup to see if something odd is going on with the networking since 10.5.6.

I'll be back...

Latest update...

I removed the following from my sysctl.conf file (and rebooted):

kern.ipc.maxsocbuf=16777216
net.inet.tcp.sockthreshold=0
net.inet.tcp.sendspace=8388608
net.inet.tcp.recvspace=8388608
net.inet.tcp.mssdflt=1440

The backup went through this time. Free memory did get down to 15MB, but the swap was never over 6.5 MB and the machine didn't choke. This was saving to the same NAS location. None of the "Treason uncloaked!" error messages in the NAS logs either.

I'll let you know if I run into any other issues.

Thanks again,

Steve

Steve Mayer wrote:net.inet.tcp.sockthreshold=0
net.inet.tcp.sendspace=8388608
net.inet.tcp.recvspace=8388608

This is the probable cause of your memory problems.

sockthreshold is the point at which the TCP/IP stack stops allocating 64K buffers (the default) and starts allocating sendspace/recvspace sized buffers instead. By setting it to 0 you're forcing all TCP/IP buffers to be the size of sendspace/recvspace. Normally these values are 8K, but you've increased them to 8M. So if you have 512 TCP sockets open the kernel will allocate 8GB of RAM just for network socket buffers!

I see two problems. First, the values for sendspace/recvspace are ridiculously high. Even the fastest fibre channel networks couldn't overrun a 8MB buffer on a modern PC. And as you've found out, anything that consumes more memory is a performance cost. In this case the performance gain of a larger buffer doesn't outweigh the performance loss of allocating so much memory. If you were running a server, had tons of memory, and a really really fast network, it might make sense to up these values to 16K or even 32K.

But you aren't running a server, so the real mystery is why you have so many TCP/IP sockets open. I suspect that sockets are timing out and getting abandoned. This leaves them allocated until they (eventually) time out and are closed. You might consult the Netgear people to find out if stray TCP sockets are to be expected when using your NAS or if there's some other problem.

James,

Thanks for the education. I had added these in a while back as I was investigating increasing network speed on my laptop. Can't say that after removing them I'm honestly seeing too much of a difference in speed.<G> Call it ignorance on my part...

As I said before, it's possible something changed in 10.5.6 that exacerbated my already flawed config... I verified that another run last night worked successfully also. I'm considering this matter closed, lesson learned, and definitely appreciate the support.

Steve