Log of #mupdf at irc.freenode.net.

 <<<Back 1 day (to 2021/06/09)Fwd 1 day (to 2021/06/11)>>>20210610 
artifexirc-bot <diego.bernardes> Hi folks I have a question about the MuPDF library. Is it ok to use it in a multithreaded application where the MuPDF resources are not shared between threads? Everything is created (context, document, etc...) and deleted in the request cycle of an HTTP call.15:23.24 
  <avih> ator: but how did you create it? like, where's the data from?15:23.50 
  <diego.bernardes> The data comes from S3, then it's passed to the library to convert the PDF to a PNG file. I'm using `fz_open_memory` and `pdf_open_document_with_stream`.15:25.59 
  <diego.bernardes> AWS S3*15:26.16 
  <avih> diego were you answering to me? i was asking ator about unicode data.15:27.00 
  <diego.bernardes> yes 🤦‍♂️15:27.15 
  <avih> well, i don't see how it's relevant to my question. i wasn't asking you if that wasn't clear.15:28.00 
  <diego.bernardes> Nevermind. I thought that you were doing a question regards to my question. Just disconsider.15:29.31 
  <avih> np15:30.37 
  <Robin_Watts> diego: I think that should be OK, with 1 minor proviso.16:32.01 
  <Robin_Watts> Some of the libs we use aren't great about multithreading and use globals. As such we lock/unlock around calls to those libs to protect the globals.16:32.31 
  <Robin_Watts> Thus you must share locks between the different contextx.16:32.55 
  <Robin_Watts> Thus you must share locks between the different contexts.16:32.57 
  <diego.bernardes> Got it.16:33.26 
  <diego.bernardes> Yeah, that's maybe the reason why I'm getting SIGSEGV in production.16:33.35 
  <diego.bernardes> I'll deploy a new version with a global context and use a cloned context at the threads.16:34.03 
  <diego.bernardes> Let's see how it goes 🤞16:34.11 
  <diego.bernardes> Yeah, maybe that's the reason why I'm getting SIGSEGV in production.16:34.28 
  <diego.bernardes> I'll deploy a new version with a global context and use a cloned context at each thread.16:34.46 
  <Robin_Watts> That will share caches etc across all the threads.16:35.53 
  <Robin_Watts> You can create new contexts each time, just make sure you use the same fz_locks_context for each one.16:37.53 
  <diego.bernardes> @Robin_Watts , when a context is created we set the value of the storage with something like `FZ_STORE_DEFAULT`, imagine that we have a global context with that value and then we clone the context on each new thread. What happens with the storage? It's a single shared cache with everyone? Or every new context can use the global cache but can still cache their own things?17:41.27 
  <diego.bernardes> I'm asking this because doing the global context looks like solved my problem, the app is running for over a hour and since then zero crashes but the memory usage is growing and growing and growing. Almost looks like a memory leak.17:41.29 
  <Robin_Watts> Every new context should share the store.17:42.24 
  <Robin_Watts> i.e. MuPDF will do its best to run within a total 'cache' size of FZ_STORE_DEFAULT bytes.17:43.27 
  <Robin_Watts> A continuing growth in memory usage does sound like a leak, yes.17:44.03 
  <Robin_Watts> We have a library 'Memento', that we can build into the library that tracks such things.17:45.16 
  <Robin_Watts> You can use that to see what blocks are leaking and why.17:45.56 
  <diego.bernardes> That's awesome, did not know about that. Yeah, for sure I'll use it. Thanks!17:46.58 
  <diego.bernardes> And this is the memory usage at the service since it was deployed an hour ago. The red line is the trend.17:47.39 
  <diego.bernardes> https://cdn.discordapp.com/attachments/770685907279282196/852604943005384704/unknown.png17:47.39 
  <diego.bernardes> @Robin_Watts , I was able to put memento on my application and got some crazy long lines. What do I need to look at here? Are events like this one?18:40.17 
  <diego.bernardes> ```18:40.20 
  <diego.bernardes> 0x38008060:(size=41696,num=1) (fz_context)18:40.21 
  <diego.bernardes> Events:18:40.22 
  <diego.bernardes> Event 1 (malloc)18:40.24 
  <diego.bernardes> 0 sample 0x0000000004333779 fz_malloc_default + 2518:40.25 
  <diego.bernardes> 0 sample 0x000000000429c453 fz_new_context_imp + 16318:40.26 
  <diego.bernardes> 0 sample 0x0000000004288ff1 init + 19318:40.28 
  <diego.bernardes> 0 sample 0x000000000406ccb0 runtime.asmcgocall + 11218:40.29 
  <diego.bernardes> ```18:40.30 
  <diego.bernardes> Where it had a malloc but did not have a `dropRef`?18:40.33 
  <diego.bernardes> At the beginning of the report output it also said this `113 mallocs, 61 frees, 1 reallocs`.18:40.38 
  <diego.bernardes> @Robin_Watts , I was able to put memento on my application and got some crazy long lines. What do I need to look at here? Events like this one?18:41.20 
  <diego.bernardes> ```18:41.22 
  <diego.bernardes> 0x38008060:(size=41696,num=1) (fz_context)18:41.23 
  <diego.bernardes> Events:18:41.25 
  <diego.bernardes> Event 1 (malloc)18:41.26 
  <diego.bernardes> 0 sample 0x0000000004333779 fz_malloc_default + 2518:41.27 
  <diego.bernardes> 0 sample 0x000000000429c453 fz_new_context_imp + 16318:41.29 
  <diego.bernardes> 0 sample 0x0000000004288ff1 init + 19318:41.30 
  <diego.bernardes> 0 sample 0x000000000406ccb0 runtime.asmcgocall + 11218:41.31 
  <diego.bernardes> ```18:41.33 
  <diego.bernardes> Where it had a malloc but did not have a `dropRef`?18:41.35 
  <Robin_Watts> By default, when you exit, Memento will run an atexit handler that lists all the unfreed blocks.18:41.36 
  <Robin_Watts> Is that part of what you're listing above?18:41.38 
  <Robin_Watts> Every allocation event (free/malloc/realloc etc) is given an event number.18:42.02 
  <Robin_Watts> Those numbers are stored at the header of the block. So that block you list above is number 1 (i.e. the very first allocation ever done).18:42.33 
  <Robin_Watts> I'm guessing that you're doing fz_new_context, but maybe not fz_drop_context() ?18:44.57 
  <diego.bernardes> Yes, this is printed at the finish of the application. And yes, that was the first block it was initialized by the Go app and I did no free on that context because it stays alive for the whole execution of the application. It's reporting correctly that I have a leak there, expected, but I have.18:45.30 
  <diego.bernardes> I'm seeing a ton of events like this:18:46.05 
  <diego.bernardes> ```18:46.07 
  <diego.bernardes> 0x7905520:(size=416,num=18) (lcms)18:46.08 
  <diego.bernardes> Events:18:46.09 
  <diego.bernardes> Event 18 (malloc)18:46.11 
  <diego.bernardes> 0 sample 0x0000000004333779 fz_malloc_default + 2518:46.12 
  <diego.bernardes> 0 sample 0x000000000433322a do_scavenging_malloc + 5818:46.13 
  <diego.bernardes> 0 sample 0x00000000043332c5 fz_malloc_no_throw + 5318:46.15 
  <diego.bernardes> 0 sample 0x000000000429697a fz_lcms_malloc + 4218:46.16 
  <diego.bernardes> 0 sample 0x000000000464b8f1 _cmsMalloc + 4918:46.17 
  <diego.bernardes> 0 sample 0x0000000004657581 cmsOpenIOhandlerFromMem + 27318:46.19 
  <diego.bernardes> 0 sample 0x0000000004659a17 cmsOpenProfileFromMem + 8718:46.20 
  <diego.bernardes> 0 sample 0x000000000429590a fz_new_icc_profile + 5818:46.21 
  <diego.bernardes> 0 sample 0x0000000004296db1 fz_new_icc_colorspace + 24118:46.22 
  <diego.bernardes> 0 sample 0x0000000004296ba2 fz_new_colorspace_context + 35418:46.24 
  <diego.bernardes> 0 sample 0x000000000429c596 fz_new_context_imp + 48618:46.25 
  <diego.bernardes> 0 sample 0x0000000004288ff1 init + 19318:46.26 
  <diego.bernardes> 0 sample 0x000000000406ccb0 runtime.asmcgocall + 11218:46.28 
  <diego.bernardes> 0x7905400:(size=24,num=17) (lcms)18:46.29 
  <diego.bernardes> ```18:46.30 
  <Robin_Watts> Right. So what other blocks is it listing? Go to pastebin.com and stick loads in there.18:46.32 
  <diego.bernardes> sure, 1sec.18:46.33 
  <diego.bernardes> https://pastebin.com/XC7kBH7i18:46.51 
  <diego.bernardes> this is the source code if you want to take a look too: https://github.com/Nitro/lazypdf/blob/main/main.c18:48.09 
  <diego.bernardes> at the report from pastebin I'm just using the `init` and `page_count` functions.18:48.10 
  <Robin_Watts> Right, so all those blocks hang off fz_context, so there is nothing surprising there.18:48.38 
  <Robin_Watts> Can you get a more representative run?18:49.08 
  <diego.bernardes> Sure, let me run for a longer period of time.18:49.26 
  <Robin_Watts> I'm in the UK here, so it's 8pm. I've got to step away. I'll check back later/tomorrow.19:03.55 
  <diego.bernardes> Sure, I'm having some problems with Go the runtime does not like memento 😅19:05.13 
  <diego.bernardes> Thanks for the help!19:05.17 
 <<<Back 1 day (to 2021/06/09)Forward 1 day (to 2021/06/11)>>> 
ghostscript.com #ghostscript