Mattermost-server: Slow Image Uploading and Thumbnail Generation

[philiplb]

Summary

When I upload an image the upload and thumbnail generation is somewhat slow.

Steps to reproduce

Using Mattermost 5.2.1 and the S3 storage.

Expected behavior

Uploading an image should be fast.

Observed behavior (that appears unintentional)

This image is 100x100px and has 6kb of size. But it takes more than 10s to upload.

It looks like this:

[amyblais]

Hi @philiplb!

Your issue might be related to this Github Issue: https://github.com/mattermost/mattermost-server/issues/9078.

The issue is most likely related to running out of memory space when initiating a file upload. Some users have had success in mitigating this by adding a swap file. This will slow file uploads considerably, but will prevent the system from running out of memory when too many files are uploaded.

These are next steps to improve this:
https://github.com/mattermost/mattermost-server/issues/8838
https://github.com/mattermost/mattermost-server/issues/8641
https://github.com/mattermost/mattermost-server/issues/8718

[philiplb]

Hi @amyblais
thank you for the answer. I'm not sure if this is memory related?
Our test setup has 15 users with < 50 messages per day. The container running Mattermost has 1GB of memory assigned.
In case of a leak, I just tried to restart the server and upload another picture. Again this one. The first time was fast enough but already the second try was slow again. A leak as cause for the slowdown would be a bit surprising as the image is only 100x100px in size and uses (png compressed) only 6kb. Uncompressed this are only 39KB of raw data. Let it be 100 with metadata and thumbnail.
I'm afraid there is no easy way for us to determine the memory usage within the container. Is there any method in Mattermost itself to see the used memory?
The log doesn't show any errors during an image upload (any ID-like things redacted):

2018-08-28T16:01:52.104575Z app[...]: {"level":"debug","ts":1535472112.1044416,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}
2018-08-28T16:01:52.138374Z app[...]: {"level":"debug","ts":1535472112.1380165,"caller":"web/handlers.go:50","msg":"GET - /api/v4/users/me/teams/.../channels"}
2018-08-28T16:01:52.138674Z app[...]: {"level":"debug","ts":1535472112.1383955,"caller":"web/handlers.go:50","msg":"GET - /api/v4/users/me/teams/.../channels/members"}
2018-08-28T16:01:53.111532Z app[...]: {"level":"debug","ts":1535472113.1113234,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}
2018-08-28T16:01:54.350832Z app[...]: {"level":"debug","ts":1535472114.3486814,"caller":"web/handlers.go:50","msg":"POST - /api/v4/files"}
2018-08-28T16:01:56.805427Z app[...]: {"level":"debug","ts":1535472116.8040295,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}
2018-08-28T16:02:03.818931Z app[...]: {"level":"debug","ts":1535472123.8159158,"caller":"web/handlers.go:50","msg":"POST - /api/v4/users/status/ids"}
2018-08-28T16:02:04.169025Z app[...]: {"level":"debug","ts":1535472124.1687942,"caller":"web/handlers.go:50","msg":"GET - /api/v4/files/.../thumbnail"}
2018-08-28T16:02:04.706222Z app[...]: {"level":"debug","ts":1535472124.706074,"caller":"web/handlers.go:50","msg":"POST - /api/v4/posts"}
2018-08-28T16:02:04.708599Z app[...]: {"level":"debug","ts":1535472124.7084892,"caller":"wsapi/websocket_handler.go:26","msg":"websocket: user_typing"}
2018-08-28T16:02:04.746012Z app[...]: {"level":"debug","ts":1535472124.7455401,"caller":"web/handlers.go:50","msg":"GET - /api/v4/files/.../preview"}
2018-08-28T16:02:04.853664Z app[...]: {"level":"debug","ts":1535472124.8535388,"caller":"web/handlers.go:50","msg":"GET - /api/v4/posts/.../files/info"}
2018-08-28T16:02:05.857551Z app[...]: {"level":"debug","ts":1535472125.857424,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}

Looking forward to the improvements! :)

[amyblais]

Thanks for the additional details @philiplb - what device and version are you seeing this on?

[philiplb]

Hi,
I'm on an early 2015 MacBook Pro (i7, 16GB RAM, SSD) with MacOS 10.13.6.
I tried the webversion with Firefox 61.0.2 and Rambox 0.5.17 which is an Electron application using Chromium 59.0.3071.115.

[philiplb]

I just had a look with the network inspector of Firefox, this endpoint just took 7.2s for the image posted above: POST /api/v4/files

[amyblais]

Hi @philiplb - I'm not able to reproduce this on a similar environment - would you like to do some testing on our nightly build server to see how the file upload experience is like there?

[philiplb]

Hi @amyblais,
thanks. I just played arround a bit and don't experience the slow performance on the nightly build server. Is it using S3? What specs does it have? Is it hosted on AWS and so doesn't have a "high" latency to S3?
Our setup is not on AWS but in a Berlin based data center. Maybe that's the cause?

[amyblais]

@philiplb Yes, we use S3 and AWS - could be the cause of the issue but I'm not 100% sure. Can you help share more details on your S3 settings? Also, do you have Debugging enabled when you observe the logs for any errors?

[philiplb]

Hi @amyblais
sure! So our datacenter is in Berlin and the S3 bucket is located in Frankfurt (eu-central-1). The following configuration is done in Mattermosts FileSettings section:

• DriverName
• AmazonS3Region
• AmazonS3Bucket
• AmazonS3AccessKeyId
• AmazonS3SecretAccessKey

The rest has its default value.

What exactly do you mean with "Debugging enabled"? The log level is set to the default which is DEBUG.

[philiplb]

Hi again, I think I found out what "Debugging enabled" means. :) Here are the logs with Amazon S3 Debugging enabled, again some IDs are redacted. And some IDs got not replaced by "..." but by "uploadID1" to "uploadID3".

2018-08-30T08:32:26.683351Z app[...]: {"level":"debug","ts":1535617946.683209,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}
2018-08-30T08:32:26.711582Z app[...]: {"level":"debug","ts":1535617946.7111053,"caller":"web/handlers.go:50","msg":"GET - /api/v4/users/me/teams/.../channels"}
2018-08-30T08:32:26.711902Z app[...]: {"level":"debug","ts":1535617946.7111075,"caller":"web/handlers.go:50","msg":"GET - /api/v4/users/me/teams/.../channels/members"}
2018-08-30T08:32:28.161514Z app[...]: {"level":"debug","ts":1535617948.1599014,"caller":"web/handlers.go:50","msg":"POST - /api/v4/channels/members/me/view"}
2018-08-30T08:32:29.643325Z app[...]: {"level":"debug","ts":1535617949.6431088,"caller":"web/handlers.go:50","msg":"POST - /api/v4/users/status/ids"}
2018-08-30T08:32:29.709680Z app[...]: {"level":"debug","ts":1535617949.7095792,"caller":"web/handlers.go:50","msg":"POST - /api/v4/files"}
2018-08-30T08:32:29.849931Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:29.851099Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test.png?uploads= HTTP/1.1
2018-08-30T08:32:29.851151Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:29.851441Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:29.851531Z app[...]: Content-Length: 0
2018-08-30T08:32:29.851951Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:29.852428Z app[...]: Content-Type: image/png
2018-08-30T08:32:29.852700Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:29.853127Z app[...]: X-Amz-Date: 20180830T083229Z
2018-08-30T08:32:29.853320Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:29.853544Z app[...]:
2018-08-30T08:32:29.854104Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:29.854171Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:29.854424Z app[...]: Date: Thu, 30 Aug 2018 08:32:30 GMT
2018-08-30T08:32:29.854657Z app[...]: Server: AmazonS3
2018-08-30T08:32:29.854882Z app[...]: X-Amz-Id-2: UyzeRKNCnNL532nt4cVOn3hRVeQzFha4CrMiKoOD8Z1ldFLgGjeeie5evPKc5t5TpweIBXXdL5k=
2018-08-30T08:32:29.855205Z app[...]: X-Amz-Request-Id: BB0E3965C12EBCA9
2018-08-30T08:32:29.855438Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:32.796175Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:32.797236Z app[...]: PUT /20180830/teams/noteam/channels/.../users/.../.../test.png?partNumber=1&uploadId=uploadID1 HTTP/1.1
2018-08-30T08:32:32.797296Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:32.797549Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:32.797818Z app[...]: Content-Length: 5877
2018-08-30T08:32:32.797908Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:32.798099Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:32.798320Z app[...]: X-Amz-Date: 20180830T083232Z
2018-08-30T08:32:32.798353Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:32.798592Z app[...]:
2018-08-30T08:32:32.798894Z app[...]: Content-Length: 0
2018-08-30T08:32:32.798946Z app[...]: Date: Thu, 30 Aug 2018 08:32:33 GMT
2018-08-30T08:32:32.799246Z app[...]: Etag: "bdc6ea48f7d49a2846038d6b82a78b7a"
2018-08-30T08:32:32.799496Z app[...]: Server: AmazonS3
2018-08-30T08:32:32.799710Z app[...]: X-Amz-Id-2: P3d5jhSnfIoD7QDJ5+tclVfOOSXoa44CZu0A6kUp7p85kjPRxGtt2eZHbR8E8boMCN5EhFxku60=
2018-08-30T08:32:32.799748Z app[...]: X-Amz-Request-Id: 92FD2F96A5532FF4
2018-08-30T08:32:32.800020Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:32.840159Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:32.841103Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test.png?uploadId=uploadID1 HTTP/1.1
2018-08-30T08:32:32.841170Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:32.841766Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:32.842308Z app[...]: Content-Length: 231
2018-08-30T08:32:32.842710Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:32.843140Z app[...]: X-Amz-Content-Sha256: 17cc14ba41554ea53b8389d37d344d2e313b5049a4c4dd0f73499cb829edc428
2018-08-30T08:32:32.843550Z app[...]: X-Amz-Date: 20180830T083232Z
2018-08-30T08:32:32.843856Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:32.844214Z app[...]:
2018-08-30T08:32:32.844603Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:32.844999Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:32.845399Z app[...]: Content-Type: application/xml
2018-08-30T08:32:32.845968Z app[...]: Date: Thu, 30 Aug 2018 08:32:33 GMT
2018-08-30T08:32:32.846339Z app[...]: Server: AmazonS3
2018-08-30T08:32:32.846683Z app[...]: X-Amz-Id-2: 4NUUkF5KogEUxpCq0per9GfRKu1D5rMB4yBsRpqrLv5ak/yeeNIBMWaGPShdH4Nd1R8Lr7g4uPk=
2018-08-30T08:32:32.847065Z app[...]: X-Amz-Request-Id: 1652F28911515178
2018-08-30T08:32:32.847420Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:33.041423Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:33.042261Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test_preview.jpg?uploads= HTTP/1.1
2018-08-30T08:32:33.042334Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:33.042490Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:33.042643Z app[...]: Content-Length: 0
2018-08-30T08:32:33.042674Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:33.042860Z app[...]: Content-Type: image/jpeg
2018-08-30T08:32:33.043081Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:33.043116Z app[...]: X-Amz-Date: 20180830T083233Z
2018-08-30T08:32:33.043294Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:33.043330Z app[...]:
2018-08-30T08:32:33.043459Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:33.043608Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:33.043631Z app[...]: Date: Thu, 30 Aug 2018 08:32:34 GMT
2018-08-30T08:32:33.043781Z app[...]: Server: AmazonS3
2018-08-30T08:32:33.043960Z app[...]: X-Amz-Id-2: o8I1lGbk9JN5y6eNDhhc3y3eHDrqSuNJfyYIBGIGzu/viFT2PtQwM0V8JFfR1QTSGDO4oEzbMBw=
2018-08-30T08:32:33.043988Z app[...]: X-Amz-Request-Id: 591D07A43FAFE8BE
2018-08-30T08:32:33.044163Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:33.578539Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:33.578618Z app[...]: PUT /20180830/teams/noteam/channels/.../users/.../.../test_preview.jpg?partNumber=1&uploadId=uploadID2 HTTP/1.1
2018-08-30T08:32:33.578883Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:33.578937Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:33.579141Z app[...]: Content-Length: 1577
2018-08-30T08:32:33.579198Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:33.579299Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:33.579537Z app[...]: X-Amz-Date: 20180830T083233Z
2018-08-30T08:32:33.579631Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:33.579786Z app[...]:
2018-08-30T08:32:33.580016Z app[...]: Content-Length: 0
2018-08-30T08:32:33.580080Z app[...]: Date: Thu, 30 Aug 2018 08:32:34 GMT
2018-08-30T08:32:33.580235Z app[...]: Etag: "14a0cfa2ff4b7b9ec66b4caec70b74ca"
2018-08-30T08:32:33.580435Z app[...]: Server: AmazonS3
2018-08-30T08:32:33.580465Z app[...]: X-Amz-Id-2: 3Stm9UimiqaNRDfQPMjolG81PRV4wG1ZIJRgn+A22ire6LFnRntNzbS046uZvS6FMF01rBeXpXA=
2018-08-30T08:32:33.580647Z app[...]: X-Amz-Request-Id: 2FCC1D777EA2C093
2018-08-30T08:32:33.580817Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:33.594483Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:33.596371Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test_thumb.jpg?uploads= HTTP/1.1
2018-08-30T08:32:33.596427Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:33.596666Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:33.596716Z app[...]: Content-Length: 0
2018-08-30T08:32:33.596997Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:33.597090Z app[...]: Content-Type: image/jpeg
2018-08-30T08:32:33.597234Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:33.597411Z app[...]: X-Amz-Date: 20180830T083233Z
2018-08-30T08:32:33.597445Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:33.597622Z app[...]:
2018-08-30T08:32:33.597902Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:33.597969Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:33.598124Z app[...]: Date: Thu, 30 Aug 2018 08:32:34 GMT
2018-08-30T08:32:33.598391Z app[...]: Server: AmazonS3
2018-08-30T08:32:33.598461Z app[...]: X-Amz-Id-2: urr5judz1cxiCnWxIasYdufG6VHK7q+pvMhgnS0a6UMqB3z8zmzFtlXacE+QoEM5SS+IA48Fcck=
2018-08-30T08:32:33.598658Z app[...]: X-Amz-Request-Id: 3456CD63EA9A4911
2018-08-30T08:32:33.598840Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:33.700771Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:39.695213Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test_preview.jpg?uploadId=uploadID2 HTTP/1.1
2018-08-30T08:32:39.695287Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:39.695393Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:39.695463Z app[...]: Content-Length: 231
2018-08-30T08:32:39.695669Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:39.695744Z app[...]: X-Amz-Content-Sha256: 201a8092f2365f124867bfb7fe266aca5d5fab35afafc389a5d99c50d1fd3c2e
2018-08-30T08:32:39.695919Z app[...]: X-Amz-Date: 20180830T083233Z
2018-08-30T08:32:39.696086Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:39.696208Z app[...]:
2018-08-30T08:32:39.704702Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:39.704775Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:39.704965Z app[...]: Content-Type: application/xml
2018-08-30T08:32:39.705041Z app[...]: Date: Thu, 30 Aug 2018 08:32:34 GMT
2018-08-30T08:32:39.705196Z app[...]: Server: AmazonS3
2018-08-30T08:32:39.705222Z app[...]: X-Amz-Id-2: th9b8oTU0o9C8LP2ld2GL/2lPo5FixL7hFtESzsf1RQMyyDEZ/8QA7QrRTtVNdfNDlMPwr27gqo=
2018-08-30T08:32:39.705393Z app[...]: X-Amz-Request-Id: C8C61F246B8F671B
2018-08-30T08:32:39.705510Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:40.059101Z app[...]: {"level":"debug","ts":1535617960.0573537,"caller":"web/handlers.go:50","msg":"POST - /api/v4/users/status/ids"}
2018-08-30T08:32:40.073468Z app[...]: {"level":"debug","ts":1535617960.057354,"caller":"web/handlers.go:50","msg":"POST - /api/v4/users/status/ids"}
2018-08-30T08:32:40.304491Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:40.305458Z app[...]: PUT /20180830/teams/noteam/channels/.../users/.../.../test_thumb.jpg?partNumber=1&uploadId=uploadID3 HTTP/1.1
2018-08-30T08:32:40.305515Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:40.305827Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:40.306149Z app[...]: Content-Length: 1845
2018-08-30T08:32:40.306444Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:40.306614Z app[...]: X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
2018-08-30T08:32:40.306837Z app[...]: X-Amz-Date: 20180830T083240Z
2018-08-30T08:32:40.307099Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:40.307395Z app[...]:
2018-08-30T08:32:40.308155Z app[...]: Content-Length: 0
2018-08-30T08:32:40.308230Z app[...]: Date: Thu, 30 Aug 2018 08:32:41 GMT
2018-08-30T08:32:40.308490Z app[...]: Etag: "3e9488da17d08160cf3aabd1ff94699c"
2018-08-30T08:32:40.308741Z app[...]: Server: AmazonS3
2018-08-30T08:32:40.309043Z app[...]: X-Amz-Id-2: 5ouKTdN8TAsOtSh/Z/IwGp026JoukwsIFh2kLkACDwg51Pdk8A7RbVvwrACRebYXi/h6yWJp8nU=
2018-08-30T08:32:40.309296Z app[...]: X-Amz-Request-Id: 4230D33C4381F6A5
2018-08-30T08:32:40.309538Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:40.360737Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:40.363339Z app[...]: POST /20180830/teams/noteam/channels/.../users/.../.../test_thumb.jpg?uploadId=uploadID3 HTTP/1.1
2018-08-30T08:32:40.363395Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:40.363641Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:40.363667Z app[...]: Content-Length: 231
2018-08-30T08:32:40.363800Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:40.363963Z app[...]: X-Amz-Content-Sha256: 21124dcd99a28a574986b4e1f7d2932ede82d1313b97fe97056dd4cfce788e73
2018-08-30T08:32:40.364010Z app[...]: X-Amz-Date: 20180830T083240Z
2018-08-30T08:32:40.364485Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:40.365032Z app[...]:
2018-08-30T08:32:40.365846Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:40.366343Z app[...]: Transfer-Encoding: chunked
2018-08-30T08:32:40.366817Z app[...]: Content-Type: application/xml
2018-08-30T08:32:40.367360Z app[...]: Date: Thu, 30 Aug 2018 08:32:41 GMT
2018-08-30T08:32:40.367866Z app[...]: Server: AmazonS3
2018-08-30T08:32:40.368164Z app[...]: X-Amz-Id-2: ZOGXbIadrlRwUpbWv4AR2Ok7K1wPJoG+PHMww8sezt+4PyIcnpCoBbTTGkKj3isiaWTevRNvFjU=
2018-08-30T08:32:40.368763Z app[...]: X-Amz-Request-Id: 6AF4615057A85D39
2018-08-30T08:32:40.369089Z app[...]: ---------END-HTTP---------
2018-08-30T08:32:40.536000Z app[...]: {"level":"debug","ts":1535617960.5354624,"caller":"web/handlers.go:50","msg":"GET - /api/v4/files/.../thumbnail"}
2018-08-30T08:32:40.599079Z app[...]: ---------START-HTTP---------
2018-08-30T08:32:40.600160Z app[...]: GET /20180830/teams/noteam/channels/.../users/.../.../test_thumb.jpg HTTP/1.1
2018-08-30T08:32:40.600210Z app[...]: Host: smfmattermost.s3-eu-central-1.amazonaws.com
2018-08-30T08:32:40.601394Z app[...]: User-Agent: Minio (linux; amd64) minio-go/v6.0.5
2018-08-30T08:32:40.601735Z app[...]: Authorization: AWS4-HMAC-SHA256 Credential=REDACTED/20180830/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=REDACTED
2018-08-30T08:32:40.601846Z app[...]: X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2018-08-30T08:32:40.602372Z app[...]: X-Amz-Date: 20180830T083240Z
2018-08-30T08:32:40.602705Z app[...]: Accept-Encoding: gzip
2018-08-30T08:32:40.602795Z app[...]:
2018-08-30T08:32:40.603124Z app[...]: HTTP/1.1 200 OK
2018-08-30T08:32:40.603430Z app[...]: Content-Length: 1845
2018-08-30T08:32:40.603502Z app[...]: Accept-Ranges: bytes
2018-08-30T08:32:40.603734Z app[...]: Content-Type: image/jpeg
2018-08-30T08:32:40.604092Z app[...]: Date: Thu, 30 Aug 2018 08:32:41 GMT
2018-08-30T08:32:40.604233Z app[...]: Etag: "ef2560ffd570daee1bb78b2ef2cf07d1-1"
2018-08-30T08:32:40.604526Z app[...]: Last-Modified: Thu, 30 Aug 2018 08:32:34 GMT
2018-08-30T08:32:40.604640Z app[...]: Server: AmazonS3
2018-08-30T08:32:40.604972Z app[...]: X-Amz-Id-2: 0P7XvbWMPZkRdhc9nz2HmAkWM0vF0srjjQb4upuDIylboStdqbfhzheD9dOhCKr8C1kitF0C9WQ=
2018-08-30T08:32:40.605016Z app[...]: X-Amz-Request-Id: 4845ECA2B8E55E08
2018-08-30T08:32:40.605251Z app[...]: ---------END-HTTP---------

[amyblais]

@philiplb,

Apologies for the delay - I will ask our developers to take a look at the logs as the next step and I'll let you know their feedback.

[amyblais]

@lieut-data

'philiplb' is seeing issues with slow image uploading on v5.2.1 with S3 (video here to illustrate) - it's not a memory issue as it happens with very small files as well and it doesn't repro on pre-release.

Can you help take a look at the logs here if they give an indication of what the issue might be before I continue to troubleshoot with 'philiplb'?

There are some more environment details here in case relevant.

[lieut-data]

Thanks for the introduction, @amyblais!

@philiplb, sorry for the trouble you're running into. The root issue here is https://mattermost.atlassian.net/browse/MM-10677. It actually doesn't have anything to do with the size of the file being uploaded, but rather with a default constant in the S3 uploading stack that results in a 576 MiB allocation for each image being uploaded. On a system with 1 GB of memory, the bug will manifest more frequently since the necessary free space may not be available at all times depending on the activity on the server.

This one has been burning a hole for a while, but just hasn't been prioritized since it only impacts installations with a "low" amount of memory. I don't have a lot of time this sprint, but let me look into the changes required and see if we can't just fix the underlying problem.

[philiplb]

@amyblais @lieut-data
Thank you very much for having a look here! As we share quite often things like screenshots, this is a bit annoying and degrades the experience quite a bit for us.

[lieut-data]

@philiplb, @zetaab has kindly submitted a fix for this issue: https://github.com/mattermost/mattermost-server/pull/9373.

We'll end up allocating a file-size buffer on upload, but in practice the now two buffers will still be much smaller than the current 576 MiB buffer being allocated internally.

I've filed https://mattermost.atlassian.net/browse/MM-12001 to track the longer-term approach to avoid even the extra buffers here, but the above PR should address the majority of cases reported, including yours. I expect this would be included in Mattermost 5.4 at the latest.

[philiplb]

@lieut-data
Great, thanks!
Curious: Any slight chance for 5.3 for this? :)

[lieut-data]

@philiplb, yeah it's worth considering. I've pinged @jasonblais to start a discussion :)

[philiplb]

@lieut-data Thank you so much. :)

[amyblais]

https://mattermost.atlassian.net/browse/MM-10677 has been resolved and tested internally and the fix will be available in v5.3 (which will be released on Sept 14th). It should provide a fix for this issue - please let us know if you still experience the issue after upgrading.

[philiplb]

Just wanted to report back that everything is fast for us now. :)