5MB attachments ASAP

[SweetVirginia]

"As an user, I would like to forward emails from my Gmail account to a Pixelated account sure that all attachments were delivered, so I don't have to worry if the recipient didn't receive all attachments"

Our alpha-testers mentioned that sometimes when they forward emails with large attachments, they don't receive all at their organizational account. The frequent attachments are .doc with images. Sometimes images go separated from the .doc and the recipient doesn't receive them all. That confuses their communication and is one of the reasons why they don't use that email account as much as they use their Gmail.

Nowadays, Gmail accepts up to 25MB attachments. But given our technical limitations, for now, 5MB helps 😃

So:

Given that I want to send an attachment up to 5MB. When I attach to the message And sent this message Then the recipient receives, downloads and open it's attachment content.

Given that I want to receive an email with a up to 5MB attachments. When I open this message Then download and open the attachment's content.

To meditate on: If the the attachment exceeds 5MB. What to do and how to inform the user? (Ask the designer ❤️ )

[re-nobre]

hey, team! @cz8s and I did the changes on the code for supporting attachments until 5MB. When we run the tests for the server we got errors in my machine and @cz8s machine, so we put the changes in a branch called 5mb_attachment and run the tests using snap CI. The functional tests are breaking. :(

I talked with @deniscostadsc and @tuliocasagrande and they are working on it now. ;)

[cz8s]

I can continue tomorrow morning. Please leave your findings here

[deniscostadsc]

We fixed the functional tests (it was just a misspelled 5mb.daata filename). We couldn't do any exploratory test, because we didn't have a working environment (dev and unstable are apparently broken).

[tuliocasagrande]

@cz8s The functional tests passed on snap, but the build kept red because of the step Trigger-pac. @deniscostadsc and I took a look and we've changed two statements that are running only on the master branch, but they were also returning failure on the other branches.

We've just edited the statements to remove those "false failures". But at the end, apparently only the master branch pipeline was updated and we're not sure if we can replicate our changes to another branches.

[cz8s]

the trigger should fail if it is not the master branch. so this is fine.

[cz8s]

I realized one thing: we could always receive 5mb attachments. This is only about sending. So I sent some big attachments and that worked very well. No problems performance wise at all. (Running the user-agent on my local laptop) Branch is now merged to master and is ready for qa

[deniscostadsc]

The code seems very good. But I was wondering if we should create a new test to check valid attachments with more than 1MB? Something like 3.5MB or 4.9MB.

[cz8s]

@deniscostadsc: we now check with a bigger attachment. Is that okay?

[tuliocasagrande]

I did some exploratory tests and I've got 3 problems:

1. Wrong attachment size exceeded message

I tested with a 5.3MB attachment and I've got the following message:

@SweetVirginia, beside changing 1MB to 5MB, is this message OK? (❤️)

2. Attaching multiple files of 5MB each

I was able to attach multiple files of 5MB each:

But I've got errors:

Unhandled Error
Traceback (most recent call last):
Failure: exceptions.OSError: [Errno 12] Cannot allocate memory

2016-08-25 22:01:43 [twisted] CRITICAL Unhandled Error
Traceback (most recent call last):
Failure: exceptions.OSError: [Errno 12] Cannot allocate memory

Unhandled Error
Traceback (most recent call last):
Failure: exceptions.OSError: [Errno 12] Cannot allocate memory

2016-08-25 22:01:45 [twisted] CRITICAL Unhandled Error
Traceback (most recent call last):
Failure: exceptions.OSError: [Errno 12] Cannot allocate memory

3. Attachment of 5MB displayed as 6.67MB

At last, I sent an email with a 5MB attachment:

And I received the attachment correctly, but it says 6.67MB:

This can be confusing to the users.

[deniscostadsc]

Awesome review @tuliocasagrande. And sorry for not been able to help until the end.

I'm quite sure the second behavior you said is a bug. We should allow 5MB in total.

Cannot allocate memory could be badder, than we thought. Because if a few user attach files at the same time, I think we'll see this error. What do you think?

[SweetVirginia]

@tuliocasagrande That message looks good, but I would like to suggest:

"This file could not be uploaded. You can send up to 5MB attachments. Choose a smaller file | Dismiss"

What do you think?

[ayoyoness]

Test1: Send one 5Mb file from Unstable (4Gb Ram)

Result:

• Success: file upload went smooth + email sent + sync success, and md5 checksum on received attachment matches.
• Note: received files shows 6.67Mb (probably due to encoding) -- May require UX-ing how to show that on the receiving end.

[varac]

@tuliocasagrande Regarding the 5mb attachment displayed as 6,67mb, this is expected (but indeed confusing behaviour). Quoting from https://en.wikipedia.org/wiki/Email_attachment#Size_limits:

In general, 10MB is considered safe for the maximum size of an email.[4] Email users can be puzzled by these limits because the MIME encoding, which typically uses Base64 adds ~33% overhead – so that a 20MB document on disk exceeds a 25MB file attachment limit.

Same behaviour happens with all mail client imo, at least i noticed this with my TB.

So what we should do is set the attachment upload limit to 10mb-30%=7mb, so the encoded mail will still not exceed the 10mb limit.

[ayoyoness]

Test2: Send two new 5Mb files from Unstable

Result:

• Success:
  • upload process great: user not allowed to add new attachment until the first one is processed.
  • both files uploaded, sequentially and got sync-ed
• Failure:
  • email was not sent and throws SMTPDeliveryError: message file too big

2016-08-30T11:29:04.126572+02:00 unstable1 pixelated-user-agent[25663]: Unhandled Error
2016-08-30T11:29:04.126589+02:00 unstable1 pixelated-user-agent[25663]: Failure: twisted.mail.smtp.SMTPDeliveryError: 552 5.3.4 Error: message file too big
2016-08-30T11:29:04.126614+02:00 unstable1 pixelated-user-agent[25663]: <<< 552 5.3.4 Error: message file too big
2016-08-30T11:29:04.126832+02:00 unstable1 pixelated-user-agent[25663]: 2016-08-30 11:29:04 [twisted] CRITICAL Unhandled Error
2016-08-30T11:29:04.126847+02:00 unstable1 pixelated-user-agent[25663]: Failure: twisted.mail.smtp.SMTPDeliveryError: 552 5.3.4 Error: message file too big
2016-08-30T11:29:04.126871+02:00 unstable1 pixelated-user-agent[25663]: <<< 552 5.3.4 Error: message file too big
2016-08-30T11:29:04.127219+02:00 unstable1 pixelated-user-agent[25663]: Unhandled error in Deferred:
2016-08-30T11:29:04.127365+02:00 unstable1 pixelated-user-agent[25663]: 2016-08-30 11:29:04 [twisted] CRITICAL Unhandled error in Deferred:
2016-08-30T11:29:04.127619+02:00 unstable1 pixelated-user-agent[25663]: --- <exception caught here> ---
2016-08-30T11:29:04.127637+02:00 unstable1 pixelated-user-agent[25663]: File "/usr/share/python/pixelated-user-agent/src/leap.mail/src/leap/mail/outgoing/service.py", line 196, in sendError
2016-08-30T11:29:04.127649+02:00 unstable1 pixelated-user-agent[25663]: twisted.mail.smtp.SMTPDeliveryError: 552 5.3.4 Error: message file too big
2016-08-30T11:29:04.127673+02:00 unstable1 pixelated-user-agent[25663]: <<< 552 5.3.4 Error: message file too big

• UI still says the email was sent -- this is already known, see #625

[ayoyoness]

This is due to the message size limit allowed in postfix

root@unstable1:~# postconf | grep message_size
message_size_limit = 10240000

which is 10Mb but the encoding of the message will make it above that (as is explained above).

[ayoyoness]

Test3: Attach 2files: 2Mb and 5Mb on unstable

Result: Success: both attachments are uploaded, email sent and received Failure: bodyless messages are not properly parsed, see #774

7Mb is the safe limit of total attachments size. This should be added on the attachment constraints:

• 5Mb max file
• 7Mb total size overall

requires analysis and UX

[ayoyoness]

In essence, The new requirements for attachment is:

• allow for multiple file attachments on the same email
• max filesize is 5Mb, individually
• total size for all attachments combined, not exceeding 7.1Mb

This is, obviously, pending parallel attachment upload loadtest assessment.

@SweetVirginia @re-nobre

[SweetVirginia]

@mnandri I'm not sure if I understand.

How long it will take for us to fix the multiple file thing? What do we have now working? The ideal is to have multiple files, but if it's harder to fix that, do you think we can do that incrementally?

1 MB attachment feels like there's no attachment at all. That's why I see 5MB for an only file as an upgrade. When we presented Pixelated they asked for larger attachments as something very important, it would be nice for them feel that we are actually working on their needs and that the pains for testing in-development software worth something.

One tweaky ux approach is to have right after the attachment clip something like: "for now you can attach only one file up to 5 MB", and have that for a few days until we have multiple files.

[ayoyoness]

@SweetVirginia

Multiple files 5Mb is already working. I'm assessing what is the cpu/memory load on a parallel/multi-user setting and see whether we need to reduce that number (5Mb or 4Mb or...). So that is still pending.

Put simply, 5Mb multiple files is not the issue here. The discussion here is about the 10Mb postfix total message size. This is default on postfix, and is adopted on the leap platform. We then, need to notify the user that he can only send at most 10Mb of attachment in a single email (multiple attachments or not). This roughly translates to actual 7Mb of attachment (technical reason explained above).

The UX component of this is really: how to tell the user that she/he can upload multiple files, each one not exceeding 5Mb and all of them can only add up to 7Mb.

Makes sense ?

[olabini]

Isn't there a problem with soledad as well where incoming attachments explode by 10x so a 5mb attachment becomes 50mb incoming? Maybe i misunderstood, but if that happens, it will be a serious scalability issue if not fixed.

[SweetVirginia]

@mnandri now it makes sense. We'll think of something.

[bwagnerr]

@olabini yes we do have that problem, that is why when Tulio tried to send 20mb of attachments inside the vagrant machine, the user agent got killed with Out of Memory error (OOM)

[olabini]

Nice. Well - that needs to be fixed before arguia (or however it's spelled) will be able to use larger attachments as well, since most of the sending will likely be internal.

[ayoyoness]

I'm not aware of the 10x factor. If true, that is a big problem. Encoding memory overhead yes, but 10x is new to me. So @shyba has kindly agreed to investigate, if true or not and from where could it come from. Anyone who knows anything please ping him... specifics, like at which stage of the incoming process causes it, or like experiments run to reproduce it, among other things... would be great

On the 20Mb, yes it is definitely a problem, in general not just on pix -- even on Gmail you could feel that it is slow even just to upload the file... that being said, a vagrant box is quite restricted in terms of resources. More importantly, the postfix 10Mb limit should just imply that we don't allow anything that is more than 5Mb. This is not a problem we can or are trying to solve now. I have checked that sending anything that is above 7Mb from other providers (used Gmail) will be bounced back by postfix (or mx?). This should guard against any 20Mb incoming attempts.

Tests so far, on dev (4GbRam, 2Cores):

• one user, 5 attachment uploads, 2reqs/s. Result: upload success, cpu goes from 4.5%, spikes at 21% and down to 12%. Memory from 1.8% to 11.5% to 8.1%.
• 5 users, 1 attachment upload each, 2reqs/s. Result: upload success, cpu goes from 5.3%, spikes at 8.6% and down to 8.5%. Memory from 2.1% to 9.6% to 8.7%.
• one user, 20 attachment uploads, 2reqs/s. Result: 2 failures ( database locked), cpu goes from 2.1%, spikes at 25.9% and down to 15.6%. Memory from 1.8% to 24.2% to 23.3%.

Patch measurements, 3 common functions:

2.5471 haha callback: function <bound method DeferredResource._cbChild of <twisted.web.util.DeferredResource instance at 0x7fc8506c7878>> (/root/junk/git_env/local/lib/python2.7/site-packages/twisted/web/util.py:143) in thread 140499075839744
2.0250 haha inlineCallback: function sync (/root/junk/git_env/src/leap.soledad.client/client/src/leap/soledad/client/sync.py:59) in thread 140499075839744
2.1577 haha inlineCallback: function add_attachment (pixelated/adapter/mailstore/leap_attachment_store.py:27) in thread 140499075839744

Assumptions/conclusions:

• possible memory leak on document save... memory never completely gets restored... @shyba is confirming... solutions: fix if easily fixable or, in the mean time, regularly restart the UA process :)
• leap_attachment_store.add_attachment blocking, needs to be dealt with: fixed/thread/process... the usual process

Suggestions on next step are welcome at this point.

Note: These are just document saving times. PGP email encryption is not measured yet.

[olabini]

I'm also a bit confused what you mean here. The GOAL is to allow for 20mb attachments (without encoding), so from the technical side we probably need to allow for 25mb to be on the safe side.

[shyba]

@olabini if I understood well, and chance is that I don't since I am looking from the outside, this issue was about 5mb as a initial usable value for having the attachment feature. Somehow the discussion went into 10MB, then 25MB. I had some thoughts on this recently which I would like to share and explain how are things as I see them. Please point any misunderstanding as it's my first take on this thread.

To begin with, I would like to start with a Wikipedia interesting phrase as @varac mentioned

As an example, when Google's gmail service increased its arbitrary limit to 25MB it warned that: "you may not be able to send larger attachments to contacts who use other email services with smaller attachment limits".[2][3] In general, 10MB is considered safe for the maximum size of an email.[4] Email users can be puzzled by these limits because the MIME encoding, which typically uses Base64 adds ~33% overhead – so that a 20MB document on disk exceeds a 25MB file attachment limit. [5]

IMHO, we have: current state of the whole platform (<5MB), current state elsewhere (10MB) and best scenario (25MB).

I believe it's good to anchor my understanding of the issue on those values, but why?

The whole travel of an attachment on our scenario could look like: web->pix->smtp->postfix->leap_mx->couchdb->soledad(server)->soledad(client)->leap_mail->soledad(client)->soledad(server)->couchdb

So, we could break our research into:

• Web->SMTP - how much memory do we use? how does that scale? What's the final size of this mail, since we decide encoding before throwing it on transport?...
• Postfix - What if the other provider denies 25MB?
• leap_mx->couchdb - mx is async, but the put_doc call uses a synchronous code from soledad.common. That can improve, but would be nice to evaluate how it's going. Specially for multiple incoming payloads. Also, the mail comes in rfc822 and MIME, then mx creates a json for couchdb. How is this encoding going (more later)? Does it has room for improvements?
• couchdb->soledad(server)->soledad(client) - How much memory costs for the server to pick this payload and pass to the client's connection and how can that be improved? Streaming? How well does the client handle asymmetrically encrypted blobs? It can't do much on this scenario, so this could be improved to bypass encdecpool, for instance.
• leap_mail -> how does it split/recode the original message into docs? How much resources does it use? How well does it handle doing this simultaneously for lots of users? Maybe worth multiprocessing? (keymanager gpg usage matters a lot here, you could talk to @meskio to try helping to solve current gpg interactions)

And answering @mnandri, thats where I am researching at the moment:

• soledad(client)->soledad(server)
• soledad<->couchdb (was greatly improved on PR8, but not yet solved)
• soledad(server) -> soledad(client)

Even this smaller subset is more complex than it looks now as there is a data flow inside of soledad client that born and dies on encdecpool/crypto modules. The latest changes on soledad included a good set of benchmarks that allowed me to make progress on this, together with a code review from @kalikaneko on the encoding/decoding of a incoming doc, that showed several mistakes and yet-to-confirm low hanging fruits. This should get even better when drebs and me finish a review against u1db to see what's changed, what can be improved and if we broke something with current code.

Some of the things we are researching:

• blob represented as unicode then encoded as json has a huge memory overhead. I suspect a 400% overhead. Check this PoC:

import json

holder = []
for i in xrange(1000):
    holder.append('{"x": "' + ('X' * 500 * 1000) + '", "y": %s}' % (i))

for idx, doc in enumerate(holder):
    holder[idx] = json.loads(doc)
    assert holder[idx]['y'] == idx

• @kalikaneko found unnecessary calls to json decode/encode together with some should-be-removed variables holding the original content. That's still being evaluated, but should account for lots of memory.
• When a doc gets encrypted, it also gets re-encoded and we are using hex instead of base64. Hex dupes the original size, while base64 has a 33% overhead. When you put the json overhead on this, this fix grows in impact.
• Memory usage initial tests showed some memory leaks after sync. I still have to pair with drebs to bring memory usage and benchmarks into our CI in order to be a reliable result, but it's definitely something I will dig in near future.
• @mnandri found some crazy cpu usage on send_docs, but I was without internet to take a look (that was today).
• encdecpool batch-queries for docs, but can only process one at a time. If you think of 100s of attachments in a batch query you can already see the process death coming. I will try to decrease it to a value that doesn't affect benchmark timings.
• if we find a clean-code-twisted-friendly way of multiprocessing, which I believe @mnandri is close to (and maybe ampoule could help as well), it should be awesome for encryption and decryption of big attachments. Anyway, the current overhead on blob representation will probably mess process communication as we need to send the data for the other process. That's why I am digging into overhead before multiprocessing.

While taking a look on the whole scenario, I started to think that this will consume quite a lot of time and lacks a definition of done. We have plenty of options:

• ijson (uses less memory and allows you to grab a key without copying the big content key... but it's slower)
• bson (uses less memory than unicode/json, but more memory than ijson. Also it's not a popular representation IMHO)
• binary (structs as @kalikaneko suggested or pyzmq) - Too much change.
• chunking or selective syncs - https://leap.se/code/issues/5752 and https://leap.se/code/issues/7667 - IMHO, it requires a lot of effort and will be unrelated to those lower hanging fruits (which will still affect it). Not discarding or something, but saying that it won't solve the core issues, just turn around them.
• ... I think I could do this list for hours. There are plenty, really, but I think I already convinced you that we need to define a clear initial goal and scope to start walking. Maybe reaching one of those radical changes on future.

If I successfully exposed my thoughts here, now you should be able to see that there is a set of changes for each size of doc that we want to support. Some of them easy and high priority (core crypto encoding, for instance) and some of them aiming huge payloads, but hard (chunking).

IMHO, core crypto enhancement on hex->base64, for instance, should get multiplied as all other overheads happens on the end result of this encoding. So a blob sized 100 on base64 turns into 133 then 1330 (guessing 10x total worst case scenario, for instance) instead of turning into 2000 (current encoding). The current code for encdecpool for instance, if limited to handle a doc at a time, could drop memory usage considerably and then be improved to be faster. This drop on memory could allow the 5MB or even 10MB sync to happen with less trouble. Replacing the underlying json encoding to, let's say, MIME (at least during encdecpool/client/server transport) could also speed up the sync transfer while getting rid of this 400% memory overhead. And so on... Until the larger changes.

Sorry if I sounded lost, but that's because this is an ongoing issue that we uncovered many stuff recently (I am about to send to leap-discuss).

As soon as we finish u1db review against current code (or parallel to that) we will start fixing those low hanging fruits and experimenting other changes. Also note that we are aware of current encdecpool bad state and a refactor is on our queue.

Related Issues that might be helpful to you and that we would love to see more input:

• https://leap.se/code/issues/7669
• https://leap.se/code/issues/7370
• https://leap.se/code/issues/5752
• https://leap.se/code/issues/7667

Feel free to ping me or schedule mumblings or pairing or fix/ask about something that I stated here. Cheers,

[ayoyoness]

@olabini yes 20Mb is the ideal scenario, but is a longer term goal. For now, we are just working on supporting 5Mb. More specifically, find out if there is a reason why we should not allow 5Mb attachment, then fix, revert or reduce the number.

@shyba i enjoyed reading your writeup. Lots to think... I look forward to the leap-discussion thread. hopefully i can read wazokazi by then :)

[varac]

So @mnandri and me sat together and investigated memory and cpu usage during attachment upload. We used the pidstat tool first to see in realtime how things evolve and later used pidstat-grapher to actually graph things over time.

Here're the graphs from a newly restarted pixelated-server, logging in as one user and uploading 5x1mb attachments, 2 reqs/s :

Cpu:

Io:

Mem:

There seems to be a memoryleak here, as you can easyly see from the mem graph. A fresh useragent starts with around 60m of RSS memory used, and after uploading/syncing it's doubled its RSS to 125m. It doesn't go down as it should to its original value (or closer), even when we logout (it frees at least ~100m but no more, so ends up at 115m RSS).

[olabini]

@mnandri - I'm a bit confused. I thought the 20mb attachment was actually a high priority requirement from our first potential installation. It sounded like a deal breaker.

@shyba - thanks for the write up. It definitely sounds like there's a lot to do here. The question in my mind is whether it even make sense to run big attachments through all these procedures. Maybe it would be better to figure out an alternative design with less overhead for attachments?

[kalikaneko]

my crazy suggestion:

1. middle term, the "right way" would be to store blobs nicely inside soledad. Those can be a) synced from any client, corporate-install or desktop, b) downloaded on demand. There are lots of fires to be put out on this regard in soledad: the mem leakage is high priority, and it's under a good track, but there are lots of low hanging fruits that can save resource consumption pretty soon too. The "syncing-links" approach, and chunking, will take more time to be implemented properly i'm afraid.

2. a short term compromise solution, that would buy time for "the right thing ™". I think it would be trivially easy to modify the flow on the pix-UA to receive the payload and do something different than storing the whole blob in a soledad doc. Some ideas:

   a) Block encrypt it on disk with a random passphrase. Store the path to the blob and the decryption passphrase on a special soledad document (this looks a lot like the syncing-links approach discussed in brazil in april and revisited more recently together with @mnandri)

   b) Use another out-of-the box, cryptographically secure solution, to store the blobs in the provider infrastructure as they arrive. I strongly suggest tahoe-lafs: https://tahoe-lafs.org/trac/tahoe-lafs . Store the write and read capabilities in a soledad doc too, and link it in the meta-doc for the mail. Then hijack the mail that the user composed, and do the work that they couldn't do, which is replacing a painfully fat attachment for a link (that, in the tahoe case, would be the one that contains the read-only capability). Then the receiving end gets a link to the file, and you can do some magic (content-type or something) if the receving end is also a pixelated instance, and do the download nicely...

So, lots of possibilities. I would be sad if whatever short-term solution is chosen is so good that it blocks the resources needed to move towards point 1.

[shyba]

@kalikaneko +1 That sounds like an amazing idea to go around it while brainstorming sync-links ideas for soledad. Also, buying time to properly fix core soledad issues before embracing big blobs is good. @olabini sorry, just saw your mention. For now, IMHO, we should fix core issues and refactor code to simplify critical buggy parts, while learning from other projects about proper ways of syncing blobs and taking the time to make it work properly. We could achieve 20MB after core fixes, but I would say this is hard to estimate. Anyway, answering the main question, figuring out a better protocol design would be awesome. This workaround @kalikaneko suggested is very close to sync-links, which may become a core feature after we close current tech debt.

[ayoyoness]

Update:

1) Document size: The document after save in soledad is larger than original attachment size but it is not 10 folds. Here is the conversion:

Attachment Size	soledad.db size
2 Mb	~2Mb
3 Mb	~5Mb
4 Mb	~6.5 Mb
5 Mb	~8Mb
7 Mb	~11.5Mb
10 Mb	~17Mb
20 Mb	~32.5Mb

2) The memory leak causes the system to eventually run out of memory. With a number of attachment uploads, the user-agent will be killed. As expected, systemd will spin it up automatically, so it is a matter of very bad user experience (much like the FPE but less worse)

3) We confirm:

• soledad.create_doc causes the memory leak
• it is cpu intensive
• and does disk IO

The following is a graph of a simple soledad.create of a single document (~5Mb), using client_side_db script,

This suggests, that a longer term solution should involve a defeToProcess approach given the intensive cpu computation.

4) Using memory_profiler on a simple soledad.create, we traced the biggest chunk of the leak to json.loads in sqlite_backends.py

@shyba there could be a case for using ijson -- or better yet yajl, apparently 600x faster :)

However, we are seeing a number of other potential source of memory leak when memory_profiler is hooked to the pixelated-user-agent. We are conducting further investigations and will give updates.

[ayoyoness]

@kalikaneko we will dig deeper on the memory-leak for now as it will be beneficial for soledad overall, not just for attachments. We will start a discussion on leap-discuss on the bigger architectural proposals with regards to attachments as it is more appropriate, with a bigger audience/various stakeholders that side... That could be even a "sequel" to @shyba's coming soon discussion :)

[olabini]

Can I just ask here - what part is the memory leak and what part is the "expected" additional size? The memory leak should be fixed irrespective - even with a deferToProcess that kind of thing can come back and bite you.

[rdevries-thoughtworks]

I hope I don't misunderstand you, but I would say: there is no expected additional size; everything that makes memory usage grow over time should be a leak, right (or am I oversimplifying now)? When we've fixed the biggest leak(s), though, it might not be worth it to spend time on some remaining small leaks.

[olabini]

I think that's an oversimplification, yes. First, are we actually talking about memory (which is RAM) - or are we talking a space leak/disk? Second, of course some additional overhead per document is expected. If nothing else, you always need an IV for something that is encrypted - so an overhead of a fixed constant, or even an overhead of 1-5% would be completely expected and not considered a leak.

A leak in general is something where memory/space goes away and isn't reclaimed when the thing in question is deleted. If that's not what is happening here, it's not a leak at all.

If the problem is that the overhead per attachment is too large, that is the problem - it's not a leak then.

[rdevries-thoughtworks]

First, are we actually talking about memory (which is RAM) - or are we talking a space leak/disk?

RAM

If the problem is that the overhead per attachment is too large, that is the problem - it's not a leak then.

There's also overhead per attachment, but that's indeed not the leak we're talking about.

where memory/space goes away and isn't reclaimed when the thing in question is deleted

Yes, where "isn't reclaimed when the thing in question is deleted" would translate to "isn't garbage collected because a reference to it is retained" for our case (GC languages).

[rdevries-thoughtworks]

After some deep digging, we've found out the following about our tools:

The memory_profiler uses psutil under the hood to measure memory in use (and increment), which gives the memory in use by the Python process from the OS's point of view:

Line #    Mem usage    Increment   Line Contents
================================================
    30     52.5 MiB      0.0 MiB   def alloc_and_dealloc():
    31    180.5 MiB    128.0 MiB       x = [2] * (2 ** 24)
    32     52.5 MiB   -128.0 MiB       del x

Alternatively, the memory in use can be calculated through the garbage collector and.

def alloc_and_dealloc():
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0017408816 bytes
    x = [2] * (2 ** 24)
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0151626896 bytes
    del x
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0017409096 bytes

These numbers can/do deviate from each other for a few reasons:

• the garbage collector doesn't calculate the memory occupied by the runtime
• the sys.getsizeof bases itself on the __sizeof__ magic method of an object, which might be overridden/incorrect
• python might not (and apparently doesn't always, read on!) clean up memory when the GC has freed it

Regarding the last point, that can be illustrated by the following code:

def alloc_and_dealloc():
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0017408816 bytes
    x = [2] * (2 ** 23)
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0084518032 bytes
    del x
    print '%010d bytes' % sum(sys.getsizeof(o) for o in gc.get_objects())  # => 0017409096 bytes

Clearly, the GC has freed the memory, but:

Line #    Mem usage    Increment   Line Contents
================================================
    35     52.7 MiB      0.0 MiB   def alloc_and_dealloc():
    36     53.4 MiB      0.7 MiB       print '%010d' % sum(sys.getsizeof(o) for o in gc.get_objects())
    37    116.9 MiB     63.5 MiB       x = [2] * (2 ** 23)
    38    117.6 MiB      0.7 MiB       print '%010d' % sum(sys.getsizeof(o) for o in gc.get_objects())
    39    117.1 MiB     -0.5 MiB       del x
    40    117.6 MiB      0.5 MiB       print '%010d' % sum(sys.getsizeof(o) for o in gc.get_objects())

... on OS level it's not freed.

The reason for this seems to be that Python tries to optimize memory allocation for small objects by not releasing it in the first place, so that it can reuse it. See e.g. here.

The question is, whether this can be the source of our memory leak. It seems unlikely that this would create a steady increase of memory usage, but some more investigation is needed. It is important to realize, anyway, that memory_profiler and the garbage collector have a different concept of 'memory in use'.

[olabini]

In general, this kind of behavior is normal for these kinds of languages. Resident memory usage by the interpreter process almost never goes down - but assuming the memory used inside of the process is freed so it's available to new Python objects, that should never really become a problem. But this situation sounds like there's an actual memory leak of things inside the python process as well.

[olabini]

Take a look at this page: https://chase-seibert.github.io/blog/2013/08/03/diagnosing-memory-leaks-python.html It describes the kinds of tools I was talking about.

[shyba]

Thanks a lot @mnandri for finding such a smaller and still heavy operation. It is way easier to dig on that rather than whole sync and still it holds the same problems as the sync, so we might be able to make a big impact here.

I was digging it with @kalikaneko and we discovered some things.

I will start by the leak as it's urgent. So, by what we could research, there is no leak in the sense of memory that can't be taken back by the garbage collector. As soon as you close soledad, the memory usage is gone, so it is working properly. Please note that I am not stating we are done, just that this isn't a leak per se, but a huge memory usage.

Memory growth under some circumstances

Script used: https://share.riseup.net/#FGhSIXeVYT9nKNf84xES-g

What it does: creates 10 docs, one at a time, of 5mb and 20mb with defer_encryption=True and False. Then, on the 10th run, it schedules a soledad.close in 20s and reactor stop in 40s.

From those 4 runs, you can notice some kind of stable memory platform, some peaks and a drop on the final tail. I will talk about what I have on them so far.

Memory platform: that huge block of memory that only goes away by closing database pools and stops growing after a while does look like a lot some kind of caching on sqlite. I am experimenting pragmas to control it, but in my humble opinion, pix should also think in it's own multiuser pragmas and unifying the database threadpools (I will get back to threads issue in a moment).

Peaks: Those come from the previous write up. They are the operation itself being executed and releases memory as soon as it's done. There is a huge overhead due json, unicode and issues previously mentioned.

The final tail drop: That's soledad.close. You can see that even changing payloads and radical configuration (defer_encryption) it still drops to the same point. That point is Soledad's memory footprint, which pix investigated in the past and decided to go out of docker. On the same process, this memory should be shared across soledad instances. This shows that stopping the thread pools and closing db connections releases memory. So, here is the catch: that's not exactly a leak, but something holding large blocks of memory on purpose. Most likely adbapi's threadpool or sqlite caches.

Why defer encryption True/False

defer_encryption turns on the encryption pool, making it encrypt docs into a staging area for sync. That means more threads and another database open (it isn't the main one). So, this test clearly shows the impact on memory of opening a database and spawning more threads under the exact same operation holding the same doc size.

Threads

There is an ongoing investigation of threads as well. Some parts of the code we control uses deferToThread in order to release the main reactor and some parts we don't control uses it for internal pools, such as Twisted's adbapi (asynchronous db-api). As I said, I think it should be good if pix investigate memory usage by unifying those threadpools into a larger one, but I will retain myself for now as I am not sure yet how big this impact is. More to come.

Next steps

On this issue, the next step for me is to refactor/fix @kalikaneko findings on bad code, replace hexlify with base64 and re-run this bench to check how much this can improve on current low hanging fruits. Then also trying out some sqlite pragmas and investigating what's allocated under each peak and under the huge memory iceberg.

Please ping me if you pick this issue. Pairing here would make things better quickly.

[rdevries-thoughtworks]

After talking to Ola, I'm not sure how useful the following information is for this issue, but since the results are so surprising (to me, at least), I'll put them here anyway.

First of all, we can see how Python reuses its claimed memory for similarly sized objects:

Line #    Mem usage    Increment   Line Contents
================================================
    30     52.9 MiB      0.0 MiB   def alloc_and_dealloc():
    31     84.9 MiB     32.0 MiB       x = [2] * (2 ** 22)
    32     84.9 MiB      0.0 MiB       del x
    33     84.9 MiB      0.0 MiB       x = [2] * (2 ** 22)

On the other hand, for a slightly larger object, new memory will be claimed:

Line #    Mem usage    Increment   Line Contents
================================================
    30     52.9 MiB      0.0 MiB   def alloc_and_dealloc():
    31     84.9 MiB     32.0 MiB       x = [2] * (2 ** 22)
    32     84.9 MiB      0.0 MiB       del x
    33    116.9 MiB     32.0 MiB       x = [2] * (2 ** 22 + 1)

In fact, we can see what size of memory Python claims:

Line #    Mem usage    Increment   Line Contents
================================================
    30     46.0 MiB      0.0 MiB   def alloc_and_dealloc():
    31     78.0 MiB     32.0 MiB       x = [2] * (2 ** 22)
    32     78.0 MiB      0.0 MiB       del x
    33    110.0 MiB     32.0 MiB       x = [2] * (2 ** 22 + 1)
    34    110.0 MiB      0.0 MiB       del x
    35    110.0 MiB      0.0 MiB       x = [2] * (2 ** 22 + 2 ** 9)
    36    110.0 MiB      0.0 MiB       del x
    37    142.0 MiB     32.0 MiB       x = [2] * (2 ** 22 + 2 ** 9 + 1)
    38    142.0 MiB      0.0 MiB       del x
    39    142.0 MiB      0.0 MiB       x = [2] * (2 ** 22 + 2 ** 9 + 2 ** 9)
    40    142.0 MiB      0.0 MiB       del x
    41    174.0 MiB     32.0 MiB       x = [2] * (2 ** 22 + 2 ** 9 + 2 ** 9 + 1)

... that is:

• a Python list of numbers needs something like 8 bytes per item (32MiB / 4Mi items)
• for all objects in a range of 2 * 9 items, or 8 bytes * 2 * 9 = 2 \ 12 bytes = 4KiB, the same memory chunk is reused (maybe the size of these chunks grows with the size of the objects)

[rdevries-thoughtworks]

We've setup an ELK stack locally (using docker) to measure memory usage over time, piping the output of pidstat into logstash. To do so:

1. Clone https://github.com/deviantony/docker-elk

2. Add the following snippet to $REPO/logstash/config/logstash.conf so it understands the log format:

   filter {
    grok {
      match => { "message" => "%{NUMBER:time:int} *%{NUMBER:uid:int} *%{NUMBER:pid:int} *%{NUMBER:pct_usr:float} *%{NUMBER:pct_system:float} *%{NUMBER:pct_guest:float} *%{NUMBER:pct_cpu:float} *%{NUMBER:cpu:int} *%{NUMBER:minflt_per_s:float} *%{NUMBER:majflt_per_s:float} *%{NUMBER:vsz:int} *%{NUMBER:rss:int} *%{NUMBER:pct_mem:float} *%{NUMBER:kb_rd_per_s:float} *%{NUMBER:kb_wr_per_s:float} *%{NUMBER:kb_ccwr_per_s:float} *%{NUMBER:iodelay:int} *" }
    }
   }

3. docker-compose up -d to start the ELK stack
4. pidstat -p $(pgrep pixelated-user) -u -d -r -h -l 1 3600 | sed 's/\([ 0-9.]*\).*/\1/' | grep -v '^$' | ncat localhost 5000 to pipe (a slightly curated version of) the pidstat output into ELK
5. Create an index (the default will do) in Kibana (http://localhost:5601/), and then a visualization with on the Y-axis 'aggregation: average' and 'field: rss', and on the X-axis 'aggregation: date histogram' and 'field: @timestamp'

Note for Mac OS: pidstat doesn't seem to exist for mac, so I ran pixelated and pidstat in a vagrant box, writing to file (or named pipe!) instead of to port 5000, and collecting that output from the host OS:

$ pidstat ... >>/var/log/pixelated/user-agent.pidstat.log # on guest OS
$ vagrant ssh pixelated -c 'sudo tail -f /var/log/pixelated/user-agent.pidstat.log' | ncat localhost 5000 # on host OS

Note on pipe buffering: because of pipe buffering, it might take some time before you see any output of the pidstat pipeline. To have more immediate feedback, use stdbuf to do e.g. line buffering: $ stdbuf -oL pidstat -p $(pgrep pixelated-user) -u -d -r -h -l 1 3600 | stdbuf -oL sed 's/\([ 0-9.]*\).*/\1/' | stdbuf -oL grep -v '^$' | ncat localhost 5000

[thaissiqueira]

We faced two different problems related to this issue. So we decided to split the efforts in two different issues. One related to attachments and other related to memory leak.