Skip to content
This repository has been archived by the owner on May 10, 2023. It is now read-only.

Wrong mtime usage for item.source_type=file converjon images - HIGH load #135

Closed
neffets opened this issue Jan 10, 2017 · 10 comments
Closed
Milestone

Comments

@neffets
Copy link
Member

neffets commented Jan 10, 2017

If you use not urls for your images, but local file-system,
the images will be copied on every request again and will be always generated again (minimum every minute)

Wrong usage in converjon/lib/source.js Line 205

  • date from file be set always to "item.source_headers.date = (new Date()).toUTCString();"

It should use the mtime from the file-system-available image. (fs.stat()).

Further it can be improved, if it can use symbolic links for /source (if symbolic links available)

@graste graste added the bug label Jan 10, 2017
@graste
Copy link
Contributor

graste commented Jan 10, 2017

Even though converjon should be used behind a caching reverse proxy that should mitigate this problem a bit it should be working better. Marked as bug.

@selfawaresoup selfawaresoup added this to the 2.7.3 milestone Jan 26, 2017
@neffets
Copy link
Member Author

neffets commented Feb 9, 2017

The problem remains.

Old image timestamp1
Request of image at timestamp2
MaxAge-Problem?

In case of:

  • timestamp1 < (now - maxage) should be ignored
  • if (timestamp2 > (now-maxage)) ist should use the generated cache
  • only if (timestamp2 + maxage < now) the image-cacheobject shall be new generated

Debug-Output

1) original Image stats

stat fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
Access: 2017-02-08 14:10:03.000000000 +0100
Modify: 2016-08-15 08:47:21.000000000 +0200
Change: 2016-08-15 08:50:04.000000000 +0200

2) .../cGc/meta file aside the generated image-cacheobject

{"headers":{"Cache-Control":"max-age=3600","date":"Mon, 15 Aug 2016 06:47:21 GMT"},"analysis":{"format":"jpeg","width":540,"height":270}}

3) stat of generated image cache-object

stat .../cGc/source/dHRvc2l6/ZV9fNTQw/XzI3MF9j/ZmVmNGJi/ZWVjNmI5/YmE1MzE3/MDk2Z
Access: 2017-02-08 22:59:39.000000000 +0100
Modify: 2017-02-08 22:59:38.000000000 +0100
Change: 2017-02-08 22:59:38.000000000 +0100

4) Debug of converjon
showing that it generates the cache-object again and over again

[DEBUG] 30 Found local file .../fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
[DEBUG] 30 Locked: source file
[DEBUG] 30 Locked: metadata
[DEBUG] 30 Locked: target file
[DEBUG] 30 Metadata is stale
[DEBUG] 30 Item directory cleared
[DEBUG] 30 Requesting source .../fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
Mon, 15 Aug 2016 06:47:21 GMT
[DEBUG] 30 Requesting analysis
[DEBUG] 30 Analysis successful
[DEBUG] 30 Writing metadata file
[DEBUG] 30 Metadata ready
[DEBUG] 30 Source file ready
[DEBUG] 30 Target file doesn't exist. Must be regenerated.
[DEBUG] 30 Applying cropping and constriants
[DEBUG] 30 Requesting image conversion
[DEBUG] 30 Image conversion successful
[DEBUG] 30 Released lock: metadata
[DEBUG] 30 Released lock: source file
[DEBUG] 30 Releasing lock: target file
"GET /?ts=1471243641&height=270&width=540&file=img%3A...%2Ffittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg HTTP 1.0" 200 61614

[DEBUG] 31 Found local file .../fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
[DEBUG] 31 Locked: source file
[DEBUG] 31 Locked: metadata
[DEBUG] 31 Locked: target file
[DEBUG] 31 Metadata is stale
[DEBUG] 31 Item directory cleared
[DEBUG] 31 Requesting source .../fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
Mon, 15 Aug 2016 06:47:21 GMT
[DEBUG] 31 Requesting analysis
[DEBUG] 31 Analysis successful
[DEBUG] 31 Writing metadata file
[DEBUG] 31 Metadata ready
[DEBUG] 31 Source file ready
[DEBUG] 31 Target file doesn't exist. Must be regenerated.
[DEBUG] 31 Applying cropping and constriants
[DEBUG] 31 Requesting image conversion
[DEBUG] 31 Image conversion successful
[DEBUG] 31 Released lock: metadata
[DEBUG] 31 Released lock: source file
[DEBUG] 31 Releasing lock: target file
"GET /?ts=1471243641&height=270&width=540&file=img%3A...%2Ffittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg HTTP 1.0" 200 61614

Proposal in case of max-age:

  • timestamp1 (original image, as stated in meta-file) can be ignored for cache-decision
  • timestamp2 (ts of generating image-cache-object) take the stat-modified-timestamp and check (timestamp2 + max-age) < now?

@neffets neffets reopened this Feb 9, 2017
@selfawaresoup
Copy link
Contributor

  • timestamp1 (original image, as stated in meta-file) can be ignored for cache-decision
  • timestamp2 (ts of generating image-cache-object) take the stat-modified-timestamp and check
    (timestamp2 + max-age) < now?

@neffets but that proposal is exactly how it worked before I changed it to using file-stats.

The cache item's timestamp is that to the current date, the moment it is created and it is used until it's max-age runs out that you can set with this config:

headers:
  Cache-Control: "max-age:3600"

This will make the items valid for 1 hour and it will not be copied again during that time.

@selfawaresoup
Copy link
Contributor

After thinking about it some more: using stat-mtime for the timestamp of the cache items is actually a regression and could severely reduce performance.

I'll revert that change and publish a new version with the "old" method that uses the time of cache-item creation.

@neffets
Copy link
Member Author

neffets commented Feb 10, 2017

Hmhm?

  • problem before was, that it never used the cache, but allways regenerated the image-cache-object
  • problem now is: that it never use the cache, but allways regenerates the image-cache-object

All with an old image.

Looking at line 219 in lib/source.js (which was changed): yes it try to use the stat of the file source_headers

The debug-log shows, that

  1. it nevershows a debug line like: Using original local file as source

  2. that ist only the decision to renews the image-cache-source-object,
    but it seems that converjon allways run at the end convert+exiftool.

I want to see the message "Metadata is still fresh" from function "meta_data_still_fresh" ath line 143 of file lib/cache.js
But it says allways "Metadata is stale"
(Should work if I use "curl" from second try on for an whole hour, for every image (new or old) if its generated at frist try)

@selfawaresoup
Copy link
Contributor

To fix the original issue here:

Can you provide the configuration for the alias that you're using? Specifically the headers section?

@neffets
Copy link
Member Author

neffets commented Feb 10, 2017

headers:
Cache-Control: "max-age=3600"

@selfawaresoup
Copy link
Contributor

Make sure that the garbage collector config is not set to 'immediate' for target files (the default value). Set it to 'cache'. Otherwise the GC will clear the generated images after a very short time regardless of their timestamp and max-age:

headers:
  Cache-Control: "max-age=3600"

garbage_collector:
  target: 'cache'

When using this configuration, clearing the entire cache and requesting the same image with the same parameters, I see one request like this:

[DEBUG] 0 Found local file test/resources/images/test_image_sparrow_smaller.jpg
[DEBUG] 0 Locked: source file
[DEBUG] 0 Locked: metadata
[DEBUG] 0 Locked: target file
[DEBUG] 0 Metadata is stale
[DEBUG] 0 Requesting source test/resources/images/test_image_sparrow_smaller.jpg
[DEBUG] 0 Requesting analysis
[DEBUG] 0 Analysis successful
[DEBUG] 0 Writing metadata file
[DEBUG] 0 Metadata ready
[DEBUG] 0 Source file ready
[DEBUG] 0 Target file doesn't exist. Must be regenerated.
[DEBUG] 0 Applying cropping and constriants
[DEBUG] 0 Requesting image conversion
[DEBUG] 0 Image conversion successful
[DEBUG] 0 Released lock: metadata
[DEBUG] 0 Released lock: source file
[DEBUG] 0 Releasing lock: target file
::1 - - Fri, 10 Feb 2017 15:47:21 GMT "GET /?file=dev:test_image_sparrow_smaller.jpg&width=800&height=300&crop=aoi_emphasis HTTP 1.1" 200 67149

And two other ones, each a few minutes minutes later:

[DEBUG] 1 Found local file test/resources/images/test_image_sparrow_smaller.jpg
[DEBUG] 1 Locked: source file
[DEBUG] 1 Locked: metadata
[DEBUG] 1 Locked: target file
[DEBUG] 1 Metadata is still fresh
[DEBUG] 1 Target file already exists
[DEBUG] 1 Released lock: metadata
[DEBUG] 1 Released lock: source file
[DEBUG] 1 Releasing lock: target file
::1 - - Fri, 10 Feb 2017 15:49:26 GMT "GET /?file=dev:test_image_sparrow_smaller.jpg&width=800&height=300&crop=aoi_emphasis HTTP 1.1" 200 67149




[DEBUG] 2 Found local file test/resources/images/test_image_sparrow_smaller.jpg
[DEBUG] 2 Locked: source file
[DEBUG] 2 Locked: metadata
[DEBUG] 2 Locked: target file
[DEBUG] 2 Metadata is still fresh
[DEBUG] 2 Target file already exists
[DEBUG] 2 Released lock: metadata
[DEBUG] 2 Released lock: source file
[DEBUG] 2 Releasing lock: target file
::1 - - Fri, 10 Feb 2017 15:52:42 GMT "GET /?file=dev:test_image_sparrow_smaller.jpg&width=800&height=300&crop=aoi_emphasis HTTP 1.1" 200 67149

@neffets
Copy link
Member Author

neffets commented Feb 10, 2017

Your test image is fresh no problem.
My original image is old.

garbage_collector now set to "cache", max-age to 3600, still problem

`[DEBUG] 2 Found local file htdocs/fotolia/essen-trinken/fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
[DEBUG] 2 Locked: source file
[DEBUG] 2 Locked: metadata
[DEBUG] 2 Locked: target file
[DEBUG] 2 Metadata is stale
[DEBUG] 2 Item directory cleared
[DEBUG] 2 Requesting source htdocs/fotolia/essen-trinken/fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
Mon, 15 Aug 2016 06:47:21 GMT
[DEBUG] 2 Requesting analysis
[DEBUG] 2 Analysis successful
[DEBUG] 2 Writing metadata file
[DEBUG] 2 Metadata ready
[DEBUG] 2 Source file ready
[DEBUG] 2 Target file doesn't exist. Must be regenerated.
[DEBUG] 2 Applying cropping and constriants
[DEBUG] 2 Requesting image conversion
[DEBUG] 2 Image conversion successful
[DEBUG] 2 Released lock: metadata
[DEBUG] 2 Released lock: source file
[DEBUG] 2 Releasing lock: target file
 "GET /?ts=1471243641&height=270&width=540&file=img%3A%2Ffotolia%2Fessen-trinken%2Ffittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg HTTP 1.0" 200 61614
[DEBUG] 3 Found local file htdocs/fotolia/essen-trinken/fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
[DEBUG] 3 Locked: source file
[DEBUG] 3 Locked: metadata
[DEBUG] 3 Locked: target file
[DEBUG] 3 Metadata is stale
[DEBUG] 3 Item directory cleared
[DEBUG] 3 Requesting source htdocs/fotolia/essen-trinken/fittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg
Mon, 15 Aug 2016 06:47:21 GMT
[DEBUG] 3 Requesting analysis
[DEBUG] 3 Analysis successful
[DEBUG] 3 Writing metadata file
[DEBUG] 3 Metadata ready
[DEBUG] 3 Source file ready
[DEBUG] 3 Target file doesn't exist. Must be regenerated.
[DEBUG] 3 Applying cropping and constriants
[DEBUG] 3 Requesting image conversion
[DEBUG] 3 Image conversion successful
[DEBUG] 3 Released lock: metadata
[DEBUG] 3 Released lock: source file
[DEBUG] 3 Releasing lock: target file
 "GET /?ts=1471243641&height=270&width=540&file=img%3A%2Ffotolia%2Fessen-trinken%2Ffittosize__540_270_cfef4bbeec6b9ba5317096e074a38794_fotolia_42317032_gerhard_seybert.jpg HTTP 1.0" 200 61614
`

Can you test with making your test-image old?
> touch -d"2001-01-01" test/resources/images/test_image_sparrow_smaller.jpg

@selfawaresoup
Copy link
Contributor

selfawaresoup commented Feb 13, 2017

The test image is also quite old. It has an mtime from 2015 so it has definitely exceeded a max-age of 3600. Just to make sure, I also tried setting its time to 2001-01-01 but that had the same result.

Did you update to the latest version 2.7.4 before testing with the garbage collector setting I suggested?

With version 2.7.3 the problem will always happen.

@graste graste closed this as completed May 10, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants