JOSM WMS/TMS cache seems to not work efficiently on slow connections

[dido]

Fetching of WMS tiles from a remote WMS server on a slow connection seem to happen always, although tiles are already in cache.

Usecase:

1. Have a WMS layer, no tiles fetched, cache cleared (cache db deleted). Internet connection is slow (tens of kb/s).
2. Download some OSM data. Wait to fetch all tiles in perimeter.
3. Pan to an adjacent perimeter, black rectangles and a hourglass appear. No tiles still fetched.
4. Pan back to the location in 2. Instead of cached tiles, black rectangles and a hourglass appear also there.

Imagery settings:
Max disk per imagery: 1 024 MB
Tiles zoom offset: +1
Other settings are default: 10 connections, tile size 512, etc.

Status messages at CMD window:
======================================

INFO: GET http://someserver.net/api/0.6/user/details (get number of unread messages) -> 200
INFO: Open file: C:\tmp\strandza.joz (778567 bytes)
[INFO] CompositeCacheManager - Instance is null, returning unconfigured instance
[INFO] ThreadPoolManager - thread_pool.default PoolConfiguration = useBoundary = [false] boundarySize = [2000] maximumPoolSize =  [150] minimumPoolSize = [4] keepAliveTime = [300000] whenBlockedPolicy = [RUN] startUpSize = [4]
[INFO] CompositeCacheManager - Setting default auxiliaries to null
[INFO] CompositeCacheManager - setting defaultCompositeCacheAttributes to [ useLateral = true, useRemote = true, useDisk = true,  maxObjs = 1000, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
[INFO] CompositeCacheManager - setting defaultElementAttributes to [ IS_LATERAL = true, IS_SPOOL = true, IS_REMOTE = true, IS_ETERNAL = false, MaxLifeSeconds = -1, IdleTime = -1, CreateTime = 1473411414821, LastAccessTime = 1473411414821, getTimeToLiveSeconds() = -1, createTime = 1473411414821 ]
[INFO] CompositeCacheConfigurator - Parsed regions []
[INFO] CompositeCacheManager - Finished configuration in 16 ms.
[INFO] CompositeCacheConfigurator - No special ElementAttribute class defined for key [jcs.region.WMS.elementattributes], using default class.
[INFO] AbstractDoubleLinkedListMemoryCache - initialized MemoryCache for WMS
[INFO] CompositeCache - Constructed cache with name [WMS] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
[INFO] BlockDiskCache - Region [WMS_BLOCK_v2] Constructing BlockDiskCache with attributes
BlockDiskAttributes
 DiskPath [C:\Users\a\AppData\Local\JOSM\cache\tiles]
 MaxKeySize [1048576]
 MaxPurgatorySize [5000]
 BlockSizeBytes [4096]
 KeyPersistenceIntervalSeconds [300]
 DiskLimitType [SIZE]
[INFO] BlockDiskCache - Region [WMS_BLOCK_v2] Cache file root directory: [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDisk - Constructing BlockDisk, blockSizeBytes [4096]
[INFO] BlockDiskKeyStore - Region [WMS_BLOCK_v2] Cache file root directory [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDiskKeyStore - Region [WMS_BLOCK_v2] Key File [C:\Users\a\AppData\Local\JOSM\cache\tiles\WMS_BLOCK_v2.key]
[INFO] BlockDiskKeyStore - Region [WMS_BLOCK_v2] Loading keys for C:\Users\a\AppData\Local\JOSM\cache\tiles\WMS_BLOCK_v2.key
[INFO] BlockDiskKeyStore - Region [WMS_BLOCK_v2] Set maxKeySize to: '1048576'
[INFO] BlockDiskKeyStore - Region [WMS_BLOCK_v2] Loaded keys from [WMS_BLOCK_v2], key count: 217; up to 1048576 will be available.
[INFO] BlockDiskCache - Region [WMS_BLOCK_v2] Block Disk Cache is alive.
[INFO] CompositeCacheConfigurator - No special ElementAttribute class defined for key [jcs.region.TMS.elementattributes], using default class.
[INFO] AbstractDoubleLinkedListMemoryCache - initialized MemoryCache for TMS
[INFO] CompositeCache - Constructed cache with name [TMS] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
[INFO] BlockDiskCache - Region [TMS_BLOCK_v2] Constructing BlockDiskCache with attributes
BlockDiskAttributes
 DiskPath [C:\Users\a\AppData\Local\JOSM\cache\tiles]
 MaxKeySize [1048576]
 MaxPurgatorySize [5000]
 BlockSizeBytes [4096]
 KeyPersistenceIntervalSeconds [300]
 DiskLimitType [SIZE]
[INFO] BlockDiskCache - Region [TMS_BLOCK_v2] Cache file root directory: [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDisk - Constructing BlockDisk, blockSizeBytes [4096]
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Cache file root directory [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Key File [C:\Users\a\AppData\Local\JOSM\cache\tiles\TMS_BLOCK_v2.key]
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Loading keys for C:\Users\a\AppData\Local\JOSM\cache\tiles\TMS_BLOCK_v2.key
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Set maxKeySize to: '1048576'
[WARN] BlockDiskCache - Region [TMS_BLOCK_v2] Resetting cache
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Saving keys to [C:\Users\a\AppData\Local\JOSM\cache\tiles\TMS_BLOCK_v2.key], key count [0]
[INFO] BlockDiskKeyStore - Region [TMS_BLOCK_v2] Finished saving keys. It took 2ms. to store 0 keys.  Key file length [4]
[INFO] BlockDiskCache - Region [TMS_BLOCK_v2] Block Disk Cache is alive.
INFO: AbstractTileSourceLayer: estimated visible tiles: 28, estimated cache size: 224
INFO: AbstractTileSourceLayer: estimated visible tiles: 28, estimated cache size: 224
INFO: AbstractTileSourceLayer: estimated visible tiles: 12, estimated cache size: 96
INFO: AbstractTileSourceLayer: estimated visible tiles: 12, estimated cache size: 96
INFO: AbstractTileSourceLayer: estimated visible tiles: 12, estimated cache size: 96
INFO: AbstractTileSourceLayer: estimated visible tiles: 12, estimated cache size: 96
INFO: Allocate for tile source layer: 96 MB of memory. Available: 1 206 MB.
INFO: Getting NaN% of area, already have NaN%, overlap NaN%

INFO: Getting 0,0% of area, already have 134,0%, overlap 34,0%

INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3062372.1084108,5157971.3081892,3062677.8565108,5158277.0562892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3062677.8565108,5157971.3081892,3062983.6046108,5158277.0562892 -> 200
INFO: Getting 0,0% of area, already have 106,7%, overlap 6,7%

INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064206.5970108,5157971.3081892,3064512.3451108,5158277.0562892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063900.8489108,5157971.3081892,3064206.5970108,5158277.0562892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3062983.6046108,5157971.3081892,3063289.3527108,5158277.0562892 -> 200
INFO: Getting 0,0% of area, already have 100,0%, overlap 0,0%

INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063289.3527108,5158277.0562892,3063595.1008108,5158582.8043892 -> 200
INFO: Getting 0,0% of area, already have 166,3%, overlap 66,3%

INFO: Getting 0,0% of area, already have 104,1%, overlap 4,1%

[INFO] CacheEventQueue - Cache event queue created: CacheEventQueue [listenerId=237599553, cacheName=WMS_BLOCK_v2]
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063595.1008108,5156136.8195892,3063900.8489108,5156442.5676892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063900.8489108,5156136.8195892,3064206.5970108,5156442.5676892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064206.5970108,5156136.8195892,3064512.3451108,5156442.5676892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063900.8489108,5155831.0714892,3064206.5970108,5156136.8195892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063289.3527108,5156136.8195892,3063595.1008108,5156442.5676892 -> 200
INFO: Getting 0,0% of area, already have 100,0%, overlap 0,0%

INFO: Getting 0,0% of area, already have 103,7%, overlap 3,7%

INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3062983.6046108,5158277.0562892,3063289.3527108,5158582.8043892 -> 200
[INFO] CacheEventQueue - Cache event queue created: CacheEventQueue [listenerId=237599553, cacheName=WMS_BLOCK_v2]
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064206.5970108,5155831.0714892,3064512.3451108,5156136.8195892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063595.1008108,5158277.0562892,3063900.8489108,5158582.8043892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064512.3451108,5155831.0714892,3064818.0932108,5156136.8195892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064512.3451108,5156136.8195892,3064818.0932108,5156442.5676892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3062677.8565108,5158277.0562892,3062983.6046108,5158582.8043892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063900.8489108,5158277.0562892,3064206.5970108,5158582.8043892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064818.0932108,5156136.8195892,3065123.8413108,5156442.5676892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063595.1008108,5155831.0714892,3063900.8489108,5156136.8195892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064818.0932108,5156748.3157892,3065123.8413108,5157054.0638892 -> 200
[INFO] CacheEventQueue - Cache event queue created: CacheEventQueue [listenerId=237599553, cacheName=WMS_BLOCK_v2]
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064818.0932108,5156442.5676892,3065123.8413108,5156748.3157892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3064818.0932108,5155831.0714892,3065123.8413108,5156136.8195892 -> 200
INFO: GET http://someserver.net/cgi-bin/mapserv?FORMAT=image/jpeg&VERSION=1.1.1&SERVICE=WMS&REQUEST=GetMap&LAYERS=orthophoto-BG-2011&STYLES=&SRS=EPSG:3857&WIDTH=512&HEIGHT=512&BBOX=3063289.3527108,5155831.0714892,3063595.1008108,5156136.8195892 -> 200
INFO: GET http://someserver.net/api/0.6/user/details (get number of unread messages) -> 200
INFO: GET http://someserver.net/api/0.6/user/details (get number of unread messages) -> 200
[INFO] CompositeCacheConfigurator - No special ElementAttribute class defined for key [jcs.region.WMTS.elementattributes], using default class.
[INFO] AbstractDoubleLinkedListMemoryCache - initialized MemoryCache for WMTS
[INFO] CompositeCache - Constructed cache with name [WMTS] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
[INFO] BlockDiskCache - Region [WMTS_BLOCK_v2] Constructing BlockDiskCache with attributes
BlockDiskAttributes
 DiskPath [C:\Users\a\AppData\Local\JOSM\cache\tiles]
 MaxKeySize [1048576]
 MaxPurgatorySize [5000]
 BlockSizeBytes [4096]
 KeyPersistenceIntervalSeconds [300]
 DiskLimitType [SIZE]
[INFO] BlockDiskCache - Region [WMTS_BLOCK_v2] Cache file root directory: [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDisk - Constructing BlockDisk, blockSizeBytes [4096]
[INFO] BlockDiskKeyStore - Region [WMTS_BLOCK_v2] Cache file root directory [C:\Users\a\AppData\Local\JOSM\cache\tiles]
[INFO] BlockDiskKeyStore - Region [WMTS_BLOCK_v2] Key File [C:\Users\a\AppData\Local\JOSM\cache\tiles\WMTS_BLOCK_v2.key]
[INFO] BlockDiskKeyStore - Region [WMTS_BLOCK_v2] Set maxKeySize to: '1048576'
[WARN] BlockDiskCache - Region [WMTS_BLOCK_v2] Resetting cache
[INFO] BlockDiskKeyStore - Region [WMTS_BLOCK_v2] Saving keys to [C:\Users\a\AppData\Local\JOSM\cache\tiles\WMTS_BLOCK_v2.key], key count [0]
[INFO] BlockDiskKeyStore - Region [WMTS_BLOCK_v2] Finished saving keys. It took 1ms. to store 0 keys.  Key file length [4]
[INFO] BlockDiskCache - Region [WMTS_BLOCK_v2] Block Disk Cache is alive.

[wiktorn]

I can't confirm this behaviour with WMS that I test with. Can you provide information, which WMS service do you use?

Does setting imagery.generic.minimum_expires to high value, like 604800000 (this is one week) help?

[dido]

Hi,

WMS service I use is restricted by IP-address. I can provide service access if you contact me privately.

[wiktorn]

Replying to dido:

WMS service I use is restricted by IP-address. I can provide service access if you contact me privately.

Did you try raising minimum_expires? Did it not help?

Can you post a screen shot of tile info? (you get it by right-clicking downloaded tile and choosing "show tile info")?

Or you can contact me via OSM Messaging: ​http://www.openstreetmap.org/user/WiktorN - so I can check, if this is a problem on server side or on JOSM side.