Bug 57023

Summary: Socache shmcb don't cache file bigger than 11k
Product: Apache httpd-2 Reporter: John Jerome <jeromep3000>
Component: mod_socache_(dbm|dc|memcache|shmcb)Assignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: normal CC: jkaluza, raphael.droz
Priority: P2    
Version: 2.4.10   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description John Jerome 2014-09-26 16:54:56 UTC
Hello,

I'm trying to use mod_socache_shmcb but it generates error when adding file bigger than 11k.

[Fri Sep 26 18:38:57.777274 2014] [cache:debug] [pid 2998] mod_cache.c(210): [client 10.11.12.20:57770] AH00750: Adding CACHE_SAVE filter for /logo_ig.png, referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.777315 2014] [cache:debug] [pid 2998] mod_cache.c(220): [client 10.11.12.20:57770] AH00751: Adding CACHE_REMOVE_URL filter for /logo_ig.png, referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.777764 2014] [cache:debug] [pid 2998] cache_storage.c(664): [client 10.11.12.20:57770] AH00698: cache: Key for entity /logo_ig.png?(null) is http://jpa.com:80/logo_ig.png?, referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.777782 2014] [cache:debug] [pid 2998] mod_cache.c(1330): [client 10.11.12.20:57770] AH00769: cache: Caching url: /logo_ig.png, referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.777786 2014] [cache:debug] [pid 2998] mod_cache.c(1336): [client 10.11.12.20:57770] AH00770: cache: Removing CACHE_REMOVE_URL filter., referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.795933 2014] [socache_shmcb:debug] [pid 2998] mod_socache_shmcb.c(490): AH00831: socache_shmcb_store (0x68 -> subcache 8)
[Fri Sep 26 18:38:57.796175 2014] [socache_shmcb:error] [pid 2998] AH00844: inserting socache entry larger (12379) than subcache data area (12280)
[Fri Sep 26 18:38:57.796210 2014] [socache_shmcb:error] [pid 2998] AH00833: can't store an socache entry!
[Fri Sep 26 18:38:57.796243 2014] [cache_socache:warn] [pid 2998] (28)No space left on device: [client 10.11.12.20:57770] AH02386: could not write to cache, ignoring: http://jpa.com:80/logo_ig_fr.png?, referer: http://10.11.12.13/
[Fri Sep 26 18:38:57.796326 2014] [socache_shmcb:debug] [pid 2998] mod_socache_shmcb.c(552): AH00837: socache_shmcb_remove (0x68 -> subcache 8)
[Fri Sep 26 18:38:57.796368 2014] [socache_shmcb:debug] [pid 2998] mod_socache_shmcb.c(566): AH00839: leaving socache_shmcb_remove successfully

The message "(28)No space left on device" is strange because I have plenty of space left.

Config is as follow:

<IfModule mod_cache.c>
        CacheMaxExpire 86400
        <IfModule mod_cache_socache.c>
                CacheSocache shmcb
                CacheSocacheMaxSize 1000000
                CacheEnable socache /
        </IfModule>
</IfModule>


Another strange thing, there is no "Shared Memory Segments" used when with 'ipcs -a' (even as root), so impossible to know where shmcb stores the cache.
Comment 1 jkaluza 2014-10-02 11:42:05 UTC
Try to set CacheSocache like this:

CacheSocache shmcb:/path/to/datafile(2048000) 

The number in braces in size of the cache in bytes.

Note that according to documentation, you should also be able to cache the files which are too big for shared memory cache into disk cache:

httpd.apache.org/docs/2.4/en/mod/mod_cache_socache.html
Comment 2 John Jerome 2014-10-02 15:59:24 UTC
Ok thank you.

Do you know how 'subcache_data_size' is calculated ?

And do you know if each subcache can contain more than one entity ?
Comment 3 John Jerome 2014-10-03 11:04:59 UTC
I've tried the fall back configuration below :


        CacheMaxExpire 86400

        CacheRoot /var/tests/kache/apache_2.4/cache/

        CacheSocache shmcb
        CacheSocacheMaxSize 1000000

        CacheQuickHandler off

        CacheDirLevels 3
        CacheDirLength 1
        CacheMinFileSize 1

        <Location />
                CacheEnable socache
                CacheEnable disk
        </Location>


But when I have this message : AH00844: inserting socache entry larger (13945) than subcache data area (12280) , I supposed that the cache on disk will be used but it isn't.



[Fri Oct 03 12:43:22.670949 2014] [authz_core:debug] [pid 5048] mod_authz_core.c(828): [client 10.151.27.181:21064] AH01628: authorization result: granted (no directives), referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671010 2014] [cache:debug] [pid 5048] mod_cache.c(502): [client 10.151.27.181:21064] AH00757: Adding CACHE_SAVE filter for /style/css/manual-print.css, referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671026 2014] [cache:debug] [pid 5048] mod_cache.c(536): [client 10.151.27.181:21064] AH00759: Adding CACHE_REMOVE_URL filter for /style/css/manual-print.css, referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671129 2014] [cache:debug] [pid 5048] cache_storage.c(664): [client 10.151.27.181:21064] AH00698: cache: Key for entity /style/css/manual-print.css?(null) is http://jpa.com:80/style/css/manual-print.css?, referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671156 2014] [cache:debug] [pid 5048] mod_cache.c(1330): [client 10.151.27.181:21064] AH00769: cache: Caching url: /style/css/manual-print.css, referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671164 2014] [cache:debug] [pid 5048] mod_cache.c(1336): [client 10.151.27.181:21064] AH00770: cache: Removing CACHE_REMOVE_URL filter., referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671544 2014] [socache_shmcb:debug] [pid 5048] mod_socache_shmcb.c(490): AH00831: socache_shmcb_store (0x68 -> subcache 8)
[Fri Oct 03 12:43:22.671558 2014] [socache_shmcb:error] [pid 5048] AH00844: inserting socache entry larger (13945) than subcache data area (12280)
[Fri Oct 03 12:43:22.671564 2014] [socache_shmcb:error] [pid 5048] AH00833: can't store an socache entry!
[Fri Oct 03 12:43:22.671573 2014] [cache_socache:warn] [pid 5048] (28)No space left on device: [client 10.151.27.181:21064] AH02386: could not write to cache, ignoring: http://jpa.com:80/style/css/manual-print.css?, referer: http://jpa.com/env.html
[Fri Oct 03 12:43:22.671620 2014] [socache_shmcb:debug] [pid 5048] mod_socache_shmcb.c(552): AH00837: socache_shmcb_remove (0x68 -> subcache 8)
[Fri Oct 03 12:43:22.671628 2014] [socache_shmcb:debug] [pid 5048] mod_socache_shmcb.c(566): AH00839: leaving socache_shmcb_remove successfully



And when I use "CacheEnable disk" alone, the cache on disk works :


[Fri Oct 03 12:57:24.958615 2014] [cache_disk:debug] [pid 5113] mod_cache_disk.c(1350): [client 10.151.27.181:21211] AH00737: commit_entity: Headers and body for URL http://jpa.com:80/style/css/manual-print.css? cached., referer: http://jpa.com/env.html



Am I doing it wrong or is the fall back configuration not possible ?
Comment 4 Christophe JAILLET 2014-10-03 18:38:40 UTC
(In reply to John Jerome from comment #2)
> Ok thank you.
> 
> Do you know how 'subcache_data_size' is calculated ?
> 

See http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/cache/mod_socache_shmcb.c?revision=1595426&view=markup#l338

You can also set loglevel to debug in order to get information logged (see link above at line 444)
Comment 5 Christophe JAILLET 2014-10-05 20:15:53 UTC
Hi,

could you try http://svn.apache.org/r1629508
This increase the average size of "small object".

With this patch, subcache_data_size goes from 12280 to 64768.
Comment 6 John Jerome 2014-10-06 09:46:51 UTC
(In reply to Christophe JAILLET from comment #5)
> Hi,
> 
> could you try http://svn.apache.org/r1629508
> This increase the average size of "small object".
> 
> With this patch, subcache_data_size goes from 12280 to 64768.

Thank you for your help Christophe, but unfortunately I won't be able to test the patch right now (maybe in a few weeks).

I managed to increase the subcache_data_size with the info given by Jan : CacheSocache shmcb:/path/to/datafile(2048000) 


My problem now is with the fall back configuration because it seems that the CacheEnable directive is exclusive.
Comment 7 Raphaƫl Droz 2015-10-11 01:04:26 UTC
Using:
CacheSocache shmcb:/path/to/datafile(10485760)
I got a subcache_data_size of 61424 I needed.


Having "disk" enabled for / and "socache" for /*.svg I can see this kind of things for a file of 600 kB
```
mod_cache_socache.c(394): AH02347: URL 'http://localhost/webfont.svg?' body larger than limit, ignoring (143732 > 102400)
mod_cache.c(1332): AH00769: cache: Caching url: /webfont.svg
mod_cache.c(1338): AH00770: cache: Removing CACHE_REMOVE_URL filter.
mod_cache.c(1731): AH00777: cache: CACHE filter was added twice, or was added where the cache has been bypassed and will be ignored: /webfont.svg
mod_cache_disk.c(1350): AH00737: commit_entity: Headers and body for URL http://localhost/webfont.svg? cached.
```

I don't know if my configuration really requested to "cache twice", but the end result is what I'd expect: cache_disk relaying cache_socache

This 102400 seems hardcoded somewhere.

**but**
trying to access a 75 kB file (greater than subcache_data_size but lower than 102400), I get:

```
cache_storage.c(664): AH00698: cache: Key for entity /style.css?(null) is http://localhost/style.css?
mod_socache_shmcb.c(527): AH00835: socache_shmcb_retrieve (0x68 -> subcache 104)
mod_socache_shmcb.c(883): AH00851: shmcb_subcache_retrieve found no match
mod_socache_shmcb.c(537): AH00836: leaving socache_shmcb_retrieve successfully
mod_cache_socache.c(494): (70015)Could not find specified socket in poll list.: AH02352: Key not found in cache: http://localhost/style.css?
mod_cache.c(502): AH00757: Adding CACHE_SAVE filter for /style.css
mod_cache.c(525): AH00758: Replacing CACHE with CACHE_SAVE filter for /style.css
mod_cache.c(536): AH00759: Adding CACHE_REMOVE_URL filter for /style.css
mod_cache.c(1332): AH00769: cache: Caching url: /style.css
mod_cache.c(1338): AH00770: cache: Removing CACHE_REMOVE_URL filter.
mod_cache.c(1731): AH00777: cache: CACHE filter was added twice, or was added where the cache has been bypassed and will be ignored: /style.css
mod_socache_shmcb.c(490): AH00831: socache_shmcb_store (0x68 -> subcache 104)
AH00844: inserting socache entry larger (76169) than subcache data area (61424)
AH00833: can't store an socache entry!
(28)No space left on device: AH02386: could not write to cache, ignoring: http://localhost/style.css?
mod_socache_shmcb.c(552): AH00837: socache_shmcb_remove (0x68 -> subcache 104)
mod_socache_shmcb.c(566): AH00839: leaving socache_shmcb_remove successfully
```

cache_disk does *NOT* relay the socache (Apache 2.4.10)
(Although I understand it's not the main issue of this bug report)