[Alpha] Kobo-UNCaGED - Calibre wireless connection

[sherman]

Yeah, I'm leaning towards memory consumption. Just did some crude profiling on my own Kobo. Over five runs, the memory usage on my Forma was as follows:
Num books: 420
Memory usage at config screen: 8929 bytes (~8.9K)
Memory usage once connected: ~49561K
Crude avg per book: 118K (may be a little high, haven't counted for any fixed overheads)

Extrapolating those numbers to 3411 books works out to around 400MB!!

I definitely need to have a think about how I could reduce this.

EDIT: Although I'm not entirely sure how 'real' the numbers are.

[bigwoof]

Originally Posted by sherman

Yeah, I'm leaning towards memory consumption. Just did some crude profiling on my own Kobo. Over five runs, the memory usage on my Forma was as follows:

okay, will try to get a memory usage snapshot from the kobo.

still not sure why Calibre crashed though. That was completely unexpected. When I ran it in non-debug mode, it never crashed. I wonder if debug mode crashed because UnCaged terminated the connection and the threads on the calibre side processing the books had a fatal error. and in debug mode, that just killed everything whereas in normal mode, the affected threads just terminated and life went on..

[bigwoof]

Originally Posted by sherman

Yeah, I'm leaning towards memory consumption. Just did some crude profiling on my own Kobo. Over five runs, the memory usage on my Forma was as follows:
Num books: 420
Memory usage at config screen: 8929 bytes (~8.9K)
Memory usage once connected: ~49561K

this is probably the reason. just tried to get a memory dump.

running kobo-uncaged *noticeably* lags the telnet session.

The last reading I got was

[root@kobo ~]# ps -o rss,args | grep /mnt/onboard/.adds/kobo-uncaged/bin/ku
280m /mnt/onboard/.adds/kobo-uncaged/bin/ku


After that, ps -o rss,args (by itself) showed a zombie ku process

84 {nm-start-ku.sh} /bin/sh /mnt/onboard/.adds/kobo-uncaged/nm-start-ku.sh
0 [ku]

and then the kobo rebooted. Looks like the kernel's OOM component triggered.

also another sign that this is using all available memory and CPU is that the battery drains by about 10-15% after running this.

[sherman]

Yeah, I think I need to have a major overhaul of how metadata is handled in KU. The current method is easy and relatively fast, but at the expense of high memory usage.

[bigwoof]

Originally Posted by sherman

Yeah, I think I need to have a major overhaul of how metadata is handled in KU. The current method is easy and relatively fast, but at the expense of high memory usage.

Hey, don't worry about it. It works well up to a certain point and more importantly works well for *your* use case -- which at some level is the most important.

If you have time, please fix it. It will be much appreciated.. :-) Otherwise, it's okay. We are still very happy you provided an alternative to the usb cable :-)

[sherman]

Did some profiling with Go's 'pprof' tool, and according to that, memory usage isn't all that high, certainly no where near what ps is reporting.

Currently, ps is reporting 30m allocated, and pprof is reporting ~5MB (it was around 7-8MB, but the garbage collector seems to be cleaning up...).

I wonder if the issue is indeed an OOM? And if so, maybe it's more around allocations rather than total memory required by KU?

EDIT: if your interested, here's a version with 'pprof' enabled. You will need Go installed to make use of it. Simply install it to your Kobo as normal, and run KU. Once KU is running, you can get memory snapshots by running go tool pprof -web http://<kobo-ip>:6060/debug/pprof/heap. This will open your default web browser with an SVG image showing memory usage at the time called.

[bigwoof]

Originally Posted by sherman

EDIT: if your interested, here's a version with 'pprof' enabled. You will need Go installed to make use of it. Simply install it to your Kobo as normal, and run KU. Once KU is running, you can get memory snapshots by running go tool pprof -web http://<kobo-ip>:6060/debug/pprof/heap. This will open your default web browser with an SVG image showing memory usage at the time called.

okay. let me see if I can get this done over the weekend. Thanks! :-)

[NiLuJe]

If you have KoboStuff installed, you'll have access to a top that actually works (htop), and you'll also be able to send kernel logs to the syslog (run klogd once).

Then, if you tail the syslog (logread -F), you should be able to see if it's indeed the kernel's OOM killer murdering KU.

[bigwoof]

Originally Posted by NiLuJe

If you have KoboStuff installed, you'll have access to a top that actually works (htop), and you'll also be able to send kernel logs to the syslog (run klogd once).

Then, if you tail the syslog (logread -F), you should be able to see if it's indeed the kernel's OOM killer murdering KU.

excellent! will install these and get some proper logging going..

[sherman]

In the meantime, I'm working on cleaning up my (memory) act. Not sure how successful I'll be yet (just started debugging gremlins after the refactor).

[sherman]

Alright, initial tests look rather promising.

As far as ps is concerned, I've reduced reduced the rss usage from ~50MB to ~15MB, so a pretty decent improvement I think.

I didn't have to massively overhaul how I deal with metadata (I'm still holding the entire set in memory), but tried to me more memory efficient by preallocating where possible, streaming JSON decoding, and attempting to avoid duplicating data structures as much as possible.

I don't think I've reduced the final working set of memory much, but rather how much 'temporary' memory is required.

[sherman]

Beware, the following testing hasn't been extensively tested. If your book library is important to you, back up your books/database just in case

Having said that, my Forma hasn't blown up so...

Here's an initial test version with the metadata refactor to hopefully reduce memory usage.

[bigwoof]

Originally Posted by sherman

Beware, the following testing hasn't been extensively tested. If your book library is important to you, back up your books/database just in case

Having said that, my Forma hasn't blown up so...

Here's an initial test version with the metadata refactor to hopefully reduce memory usage.

Thanks! can't test this today. visiting relatives with the little one. Will try tomorrow after backing up everything.. :-)

[bigwoof]

Originally Posted by bigwoof

Thanks! can't test this today. visiting relatives with the little one. Will try tomorrow after backing up everything.. :-)

okay. ran a test today.

with the metadata version and NiLuJe's kobo tools. interesting to say the least

1. started ku and ran htop in a telnet shell. started klogd as well

htop showed that the memory usage up to the point of connection (where ku is reading the book list before connecting) is okay. about 280M and the telnet shell and htop were snappy. CPU usage was 100% for a while and then dropped to 10-20%

2. ku connected to calibre

memory usage shot up to 430M with 100% CPU but telnet and htop are still very responsive. so far so good.

calibre task is reading book list

3. calibre finishing reading the book list and switches to converting books and sending them

memory usage on kobo shoots up to 471M and 100% CPU htop just hangs.. I thought the WiFi disconnected to be honest but I can control C out to the command line and telnet is just super slow.. I can restart htop but the display never shows up.

calibre shows the task as sending metadata

Kobo reboots

4. When reading the syslog, I can't replicate the reboot crash.

But this behavior is consistent. ku connects, calibre starts the tasks. right before the first book is transferred, ku disconnects with this error in the syslogs

Jan 3 10:18:33 nickel: ( 1079.309 @ 0x3541df0 / packetdump.warning) "http://127.0.0.1:8181/messages" => "Connection closed"

calibre then fails all the conversion tasks

not sure why monitoring the syslog stops the reboot but I'll keep trying. the syslog is not logging to disk and I'm not sure I want to tell it too.

also two additional things.

1. if the calibre metadata file on kobo is empty (0 bytes) which happens after ku crashes for me, next time I start ku, it will not connect to calibre. it will just pop up the finished message during the metadata reading portion. this seems like a bad chicken and egg problem.

2. the files that were transfered were just put into the top-level /mnt/onboard directory. how do I get it to use the default <author name as directory>/<filename> convention?

I'll keep trying to get a reboot crash monitored in syslog. exciting!! :-)

[NiLuJe]

ssh/telnet slowing down to a crawl while you're saturating the Wi-Fi with... Wi-Fi transfers makes perfect sense, FWIW.

It'd also be consistent with a system going OOM, which makes this a bit tricky to diagnose...

Enter USBNet! That way you'd get rid of the "is it Wi-Fi?" factor .

----

EDIT: Re-reading the message, a reboot would imply either nickel hangs because the system is OOM, tries to swap, but can't because there's no swap, and that makes nickel so slow that it trips sickel's watchdog and forces a reboot. (Or nickel gets OOM-killed, sickel detects that, and reboots).

So what does the kernel say, exactly? Running klogd first means you get a timestamped kernel log in your syslog: an OOM-kill would be visible there.

(Which, given the RAM usage you're describing, is most likely what's happening, as I can't imagine the Libra having more than the usual 512MB of RAM ).

----

EDIT²: It's 4AM, so I'm a bit slow ;p. Is nickel still alive and responsive and how's the RAM usage when you happen to check the syslog and stuff just breaks at the first book?