Bug 320753 - Dynamic memory usage limit doesn't take into account virtual memory exhaustion
Summary: Dynamic memory usage limit doesn't take into account virtual memory exhaustion
Status: CONFIRMED
Alias: None
Product: okular
Classification: Applications
Component: general (show other bugs)
Version: 0.16.2
Platform: Ubuntu Linux
: NOR crash
Target Milestone: ---
Assignee: Okular developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-06-05 06:44 UTC by Martin M
Modified: 2020-12-02 09:20 UTC (History)
4 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments
valgrind pdftoppm output (80.97 KB, text/plain)
2013-06-06 15:34 UTC, Fabio D'Urso
Details
My full valgrind pdf2ppm output (338.91 KB, application/octet-stream)
2013-06-07 20:21 UTC, Martin M
Details
Valgrind output of okular on the problem file (45.22 KB, application/x-gzip)
2013-06-08 19:39 UTC, Martin M
Details
Valgrind output with okular-dbg installed (44.54 KB, application/x-gzip)
2013-06-10 05:38 UTC, Martin M
Details
Valgrind output without searching (34.64 KB, application/x-gzip)
2013-06-10 11:03 UTC, Martin M
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martin M 2013-06-05 06:44:52 UTC
Application: okular (0.16.2)
KDE Platform Version: 4.10.2
Qt Version: 4.8.4
Operating System: Linux 3.8.0-22-generic i686
Distribution: Ubuntu 13.04

-- Information about the crash:
- What I was doing when the application crashed:

I was searching "ctrl+f" for a short string in a large PDF (38 MB, 273 pages). After pressing F3 a few times, Okular crashed. I can repeat the crash.

- Custom settings of the application:

I have the memory setting "greedy" (my Swedish settings dialog says "glupsk") and I have close to 100 yellow marker notes in this document.

-- Backtrace:
Application: Okular (okular), signal: Segmentation fault
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
[Current thread is 1 (Thread 0xb4d57740 (LWP 11383))]

Thread 3 (Thread 0xb0cf3b40 (LWP 11390)):
#0  0xb53eda5b in ?? () from /lib/i386-linux-gnu/libglib-2.0.so.0
#1  0xb53edd68 in g_mutex_unlock () from /lib/i386-linux-gnu/libglib-2.0.so.0
#2  0xb53aa2a8 in g_main_context_dispatch () from /lib/i386-linux-gnu/libglib-2.0.so.0
#3  0xb53aa750 in ?? () from /lib/i386-linux-gnu/libglib-2.0.so.0
#4  0xb53aa831 in g_main_context_iteration () from /lib/i386-linux-gnu/libglib-2.0.so.0
#5  0xb60a4c3f in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#6  0xb60713ec in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#7  0xb60716e1 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#8  0xb5f5cfec in QThread::exec() () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#9  0xb6050f2d in ?? () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#10 0xb5f5fb18 in ?? () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#11 0xb5482d78 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
#12 0xb5cce3de in clone () from /lib/i386-linux-gnu/libc.so.6

Thread 2 (Thread 0xaf17db40 (LWP 11712)):
[KCrash Handler]
#6  0xb5d142ea in ?? () from /lib/i386-linux-gnu/libc.so.6
#7  0xb0f0d210 in Splash::clear(unsigned char*, unsigned char) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#8  0xb0e1f9bf in SplashOutputDev::drawSoftMaskedImage(GfxState*, Object*, Stream*, int, int, GfxImageColorMap*, bool, Stream*, int, int, GfxImageColorMap*, bool) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#9  0xb0e70aac in Gfx::doImage(Object*, Stream*, bool) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#10 0xb0e70f91 in Gfx::opXObject(Object*, int) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#11 0xb0e652ca in Gfx::execOp(Object*, Object*, int) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#12 0xb0e6c90f in Gfx::go(bool) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#13 0xb0e6ce05 in Gfx::display(Object*, bool) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#14 0xb0eb23f3 in Page::displaySlice(OutputDev*, double, double, int, bool, bool, int, int, int, int, bool, bool (*)(void*), void*, bool (*)(Annot*, void*), void*) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#15 0xb0eb8c69 in PDFDoc::displayPageSlice(OutputDev*, int, double, double, int, bool, bool, bool, int, int, int, int, bool (*)(void*), void*, bool (*)(Annot*, void*), void*) () from /usr/lib/i386-linux-gnu/libpoppler.so.28
#16 0xb0fdf2f5 in Poppler::Page::renderToImage(double, double, int, int, int, int, Poppler::Page::Rotation) const () from /usr/lib/i386-linux-gnu/libpoppler-qt4.so.4
#17 0xb1054297 in ?? () from /usr/lib/kde4/okularGenerator_poppler.so
#18 0xb2386e92 in ?? () from /usr/lib/libokularcore.so.2abi1
#19 0xb5f5fb18 in ?? () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#20 0xb5482d78 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
#21 0xb5cce3de in clone () from /lib/i386-linux-gnu/libc.so.6

Thread 1 (Thread 0xb4d57740 (LWP 11383)):
#0  0xb76e4424 in __kernel_vsyscall ()
#1  0xb5cc9377 in syscall () from /lib/i386-linux-gnu/libc.so.6
#2  0xb5f5e3b7 in ?? () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#3  0xb5f59f9c in QMutex::lockInternal() () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#4  0xb5f5a270 in QMutex::lock() () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#5  0xb10510d5 in ?? () from /usr/lib/kde4/okularGenerator_poppler.so
#6  0xb2384b65 in Okular::Generator::generateTextPage(Okular::Page*) () from /usr/lib/libokularcore.so.2abi1
#7  0xb236c1f8 in Okular::Document::requestTextPage(unsigned int) () from /usr/lib/libokularcore.so.2abi1
#8  0xb23717a6 in ?? () from /usr/lib/libokularcore.so.2abi1
#9  0xb6084b4a in QMetaCallEvent::placeMetaCall(QObject*) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#10 0xb608e48b in QObject::event(QEvent*) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#11 0xb65e5c7c in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /usr/lib/i386-linux-gnu/libQtGui.so.4
#12 0xb65e8b94 in QApplication::notify(QObject*, QEvent*) () from /usr/lib/i386-linux-gnu/libQtGui.so.4
#13 0xb715ed01 in KApplication::notify(QObject*, QEvent*) () from /usr/lib/libkdeui.so.5
#14 0xb607290e in QCoreApplication::notifyInternal(QObject*, QEvent*) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#15 0xb6076721 in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#16 0xb6076a8c in QCoreApplication::sendPostedEvents(QObject*, int) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#17 0xb60a4aa4 in ?? () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#18 0xb53aa3b3 in g_main_context_dispatch () from /lib/i386-linux-gnu/libglib-2.0.so.0
#19 0xb53aa750 in ?? () from /lib/i386-linux-gnu/libglib-2.0.so.0
#20 0xb53aa831 in g_main_context_iteration () from /lib/i386-linux-gnu/libglib-2.0.so.0
#21 0xb60a4c21 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#22 0xb669ca5a in ?? () from /usr/lib/i386-linux-gnu/libQtGui.so.4
#23 0xb60713ec in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#24 0xb60716e1 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#25 0xb60773fa in QCoreApplication::exec() () from /usr/lib/i386-linux-gnu/libQtCore.so.4
#26 0xb65e3fc4 in QApplication::exec() () from /usr/lib/i386-linux-gnu/libQtGui.so.4
#27 0x0804e46e in ?? ()
#28 0xb5bf6935 in __libc_start_main () from /lib/i386-linux-gnu/libc.so.6
#29 0x0804f0a9 in _start ()

Reported using DrKonqi
Comment 1 Albert Astals Cid 2013-06-05 22:01:31 UTC
You sure it's related to searching? The backtrace seems to imply it's crashing on just rendering? Can you make it crash by just navigating all the pages of the document?
Comment 2 Martin M 2013-06-06 10:53:59 UTC
Yes, now I see that I can make it crash just by navigating. Scrolling through the document,pressing page down and page up, (while it is being loaded in the background, I assume) also crashes Okular after a while.
Comment 3 Albert Astals Cid 2013-06-06 11:03:22 UTC
Can you please attach the document?
Comment 4 Martin M 2013-06-06 11:46:03 UTC
Sure. The file is too large to attach, but here's a dropbox link to it
https://www.dropbox.com/s/n3k4vdplmceagkt/ICRA-2013-Digest.pdf
Comment 5 Fabio D'Urso 2013-06-06 12:32:23 UTC
No crash here by just scrolling (Fedora x86 32-bit, poppler 0.20.2 with lots of backported patches). What is your Poppler version (pdfinfo -v)?
You said it also crashes if you search some text, what text exactly?

Can you please run "kdebugdialog", enable all okular entries and run okular from the shell?
After opening the document you'll see lots of debug output. Just before the crash you should see something like:
okular(18020)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 223x315@64 async == true isTile == false
Can you paste that line? (the number after @ is the zero-based page on which the crash is happening)

Thank you.
Comment 6 Martin M 2013-06-06 13:06:36 UTC
I tried running from the command line as you suggested. This time it was harder to provoke a crash. I scrolled up and down through the document a few times, and it worked OK. I also did a few searches, and it worked OK. Finally, I searched for "navigation" a few times, and then it crashed.

The lines you asked for are pasted here:
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@189 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@188 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@191 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@187 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@192 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@194 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@195 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@197 async == true isTile == false
okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@181 async == true isTile == false

I also get a ton of lines (a few thousand) like: 
okular(19505)/okular (app) Okular::Document::requestPixmaps: request id=3 651x922@270
with different page numbers at the end

I have pdfinfo version 0.20.5
Comment 7 Fabio D'Urso 2013-06-06 14:21:05 UTC
Tried with poppler 0.20.5, still no crash here :/

Yes, lines like
  okular(19505)/okular (app) Okular::Document::requestPixmaps: request id=3 651x922@270
list all pending requests, which are then processed sequentially. Lines like
  okular(19505)/okular (app) Okular::DocumentPrivate::sendGeneratorPixmapRequest: sending request id=3 1532x2167@181 async == true isTile == false
tell what's actually being processed right now (in this case a 1532x2167 rendering of page 182).

I can see that page, and I see you've added annotations on it, so you see it too. It seems this bug doesn't happen always. Let's wait to see if someone else manages to reproduce it.
I've also searched for "navigation", and it reaches the end of the document without any issue.

@Albert: In the meantime I'm running pdftoppm on each page through valgrind memcheck.
Comment 8 Fabio D'Urso 2013-06-06 15:34:36 UTC
Created attachment 80346 [details]
valgrind pdftoppm output

As said, I've run
seq 1 273 | while read X; do echo pdftoppm -f $X -l $X ICRA-2013-Digest.pdf; valgrind pdftoppm -f $X -l $X ICRA-2013-Digest.pdf > /dev/null; done
I'm attaching the output (I've removed output for pages that produced no errors).
Note: pdftoppm is poppler 0.20.5
I don't see anything that can cause a crash.
Comment 9 Albert Astals Cid 2013-06-06 20:41:12 UTC
bugzilla@eyra.se can you run same command than Fabio and attach the output?

@Fabio: Well the uninitialized values are never cool, if they happen in an if they can make the code do weird stuff
Comment 10 Martin M 2013-06-07 20:21:50 UTC
Created attachment 80385 [details]
My full valgrind pdf2ppm output

Generated with

seq 1 273 | while read X; do echo pdftoppm -f $X -l $X ICRA-2013-Digest.pdf >> valgrind-output; nice valgrind pdftoppm -f $X -l $X ICRA-2013-Digest.pdf 2>> valgrind-output > /dev/null; done
Comment 11 Albert Astals Cid 2013-06-08 18:48:36 UTC
Ok, so the same uninitialzed values than Fabio gets, as a last thing, can you plese run

valgrind okular myfile.pdf

try to go to the file that causes the crash and also attach the output?
Comment 12 Martin M 2013-06-08 19:39:31 UTC
Created attachment 80400 [details]
Valgrind output of okular on the problem file

Here's the command line I used:
valgrind okular ICRA-2013-Digest.pdf 2>valgrind-okular-output

What I did was to open the file and search for "navigation" a few times, until it crashed.
Comment 13 Fabio D'Urso 2013-06-09 11:59:05 UTC
So it seems it's not Poppler's fault. Weird....
QPainter::begin: Paint device returned engine == 0, type: 3
QPainter::end: Painter not active, aborted

It might be something bad happening in the PagePainter class, but it's a hard to say what's going on in that stack trace full of ???s, maybe installing okular-dbg can help.
Comment 14 Albert Astals Cid 2013-06-09 22:24:21 UTC
bugzilla@eyra.se: Can you confirm every time it crashes you first get this QPainter::begin: Paint device returned engine == 0, type: 3
QPainter::end: Painter not active, aborted

Thing?
Comment 15 Martin M 2013-06-10 05:38:29 UTC
Created attachment 80417 [details]
Valgrind output with okular-dbg installed

I installed okular-dbg and reran 
valgrind okular ICRA-2013-Digest.pdf 2>valgrind-okular-output2
Again, I searched for "navigation" until Okular crashed, which was at some point after page 83. However, the reason for the crash this time seems to be that valgrind ran out of memory. I have 16 GB RAM, but run 32-bit Kubuntu with PAE. I don't see any "Painter not active" messages this time.
Comment 16 Fabio D'Urso 2013-06-10 07:33:53 UTC
(In reply to comment #15)
> However, the reason for the crash this time seems to be
> that valgrind ran out of memory. I have 16 GB RAM, but run 32-bit Kubuntu
> with PAE. I don't see any "Painter not active" messages this time.
Makes sense, the algorithm that decides when to stop allocating only looks at the amount of physical memory, and it ignores the fact that you can't allocate more than 3GB under 32-bit linux.

@Albert: In the light of this, the "QPainter::begin: Paint device returned engine == 0, type: 3" might be a result of a failed allocation too, what do you think? A failed new is supposed to throw an exception instead of returning NULL, but it's possible that Qt is using plain malloc or nothrow new somewhere.
Comment 17 Martin M 2013-06-10 08:25:11 UTC
I just tried to run the same thing again, and now I was able to search through the document until okular asked if I wanted to continue from the beginning. The difference this time was that I waited long enough to let the whole document load before starting to search (I have the "greedy" performance setting, so it reads in all the pages in the background). No valgrind crash, and no okular crash.

(Thanks a lot for all your help, by the way!)
Comment 18 Martin M 2013-06-10 11:03:28 UTC
Created attachment 80421 [details]
Valgrind output without searching

Maybe the problem also has to do with which monitor output I am using. 

The attached log is the output from valgrind when just opening the document and let it sit and load all the pages, without searching. I just ran 
valgrind okular ICRA-2013-Digest.pdf 2>valgrind-okular-output5
and went for lunch, and this crash report is what I had when I came back.

This time, the okular window was at my laptop screen, which is 1920x1080. Last time, when I didn't get a crash, the window was open on the external VGA monitor, which is 1280x1024.
Comment 19 Fabio D'Urso 2013-06-10 11:46:21 UTC
Yes, that's surely what makes the difference between a crash or not. I've done some calculations.

On your 1920x1080 monitor each page is 1532x2167 pixels (according to the last log you posted).
Since images are stored as ARGB that makes for 1532x2167x4 = 13,2 MB per page.
13,2 MB x 273 pages = 3,6 GB, which is above the 3 GB virtual memory limit.
Indeed, this last stack trace is Poppler failing to allocate memory.

I don't know how big images are on your 1280x1024 monitor because I have no logs.
Assuming that page size is proportional to monitor width, the total memory usage would be:
3,6 GB x ( 1280 / 1920 )^2 = 1.6 GB, which is well below the 3 GB barrier.
Feel free to post a log on your 1280x1024 monitor (no need to use valgrind) to confirm/deny my calculations.

So it makes sense that we don't go out out of memory on your 1280x1024 monitor, whereas we do on the 1920x1080 one.

To sum up, we have this bug:
 Our dynamic memory usage limit doesn't take into account virtual memory exhaustion.

(In reply to comment #17)
> (Thanks a lot for all your help, by the way!)
Thank you for caring about okular!  :D
Comment 20 Martin M 2013-06-10 12:09:48 UTC
The image sizes on the 1280x1024 monitor is 1017x1439 pixels, according to the output below

okular(12441)/okular (app) Okular::Document::requestPixmaps: request id=3 1017x1439@272

So that would mean 5.8 MB/page, and indeed 1.6 GB for the whole document. Running htop tells me that okular uses 1662 MB virtual memory and 1555 MB res memory.
Comment 21 Albert Astals Cid 2014-05-11 11:32:55 UTC
Martin, do you still have this setup?

We have a patch that may or may not fix this but since none of us have a similar setup to yours we can't confirm it fixes it or not.

Also would you be able to compile okular with a patch we provide you?
Comment 22 Martin M 2014-05-12 04:42:24 UTC
I have almost the same setup, but Okular has been updated to 0.16.5. And yes, I can compile a patched Okular. So if you send the patch I'd be happy to try it.
Comment 23 Albert Astals Cid 2014-05-20 21:53:52 UTC
Actually can you save this


#include <sys/time.h>
#include <sys/resource.h>
#include <stdio.h>

int main(int argc, char *argv[])
{
    struct rlimit rlim;
    int res = getrlimit(RLIMIT_AS, &rlim);
    printf("%d %lu %lu\n", res, rlim.rlim_cur, rlim.rlim_max);
}


 to a file named main.cppp and run
g++ main.cpp
./a.out

And attach the output?
Comment 24 Martin M 2014-05-21 07:32:28 UTC
Sure. The output is:
0 4294967295 4294967295

Is that good?
Comment 25 Albert Astals Cid 2014-05-23 18:19:40 UTC
Well, it means your maximum allocation in a single program it's 4GB, is that correct for your setup?
Comment 26 Martin M 2014-05-26 05:07:42 UTC
Yes, that should be correct. I have 16 GB RAM and I am running a 32-bit PAE kernel.
Comment 27 Albert Astals Cid 2014-06-17 22:12:21 UTC
Great that is good. Now I only need some time to code this properly :)
Comment 28 Justin Zobel 2020-12-02 01:33:26 UTC
(In reply to Albert Astals Cid from comment #27)
> Great that is good. Now I only need some time to code this properly :)

Hey Albert, did this end up being coded and pushed to okular?
Comment 29 Albert Astals Cid 2020-12-02 09:20:29 UTC
I don't remember, i don't think so.