[ColdBox 3.6.0] - Exceptions being thrown at certain time of day.

Communities ColdBox HMVC
1

I seem to be having a problem every day from 2am (local time) to 4am. At this point the website seems to be unresponsive. I have set the request time out setting in CF to 600 seconds to make sure things are not dying and throwing this errror. I have included the stack trace at the bottom and induced a logbox file from the DB where you can see the time that it takes to clear the cache go up exponentially.
I have also noted that around 02:00 every night, the caching reap seems to take a long time. Here are some examples. The amount of time and ms for the reap continues to increase until about 04:00 and then things run normally. I am using the default cachebox.cfc configuration which is posted below. However, during this time period which is just about an hour, users are subject to getting exception errors. Also, without restarting the service it returns to normal all by itself about 4am.

Please let me know if you need more setting details or any other information. Right now, I am not sure what the problem is.

Server information:
CF10 Enterprise 64 Bit
RHET 5.0 64bit
4GB of ram
and it is a Virtual Server

Thanks!

CacheBox.cfc

/**

  • Configure CacheBox for ColdBox Application Operation
    */
    function configure(){

// The CacheBox configuration structure DSL
cacheBox = {
// LogBox config already in coldbox app, not needed
// logBoxConfig = “coldbox.system.web.config.LogBox”,

// The defaultCache has an implicit name “default” which is a reserved cache name
// It also has a default provider of cachebox which cannot be changed.
// All timeouts are in minutes
defaultCache = {
objectDefaultTimeout = 120, //two hours default
objectDefaultLastAccessTimeout = 30, //30 minutes idle time
useLastAccessTimeouts = true,
reapFrequency = 2,
freeMemoryPercentageThreshold = 0,
evictionPolicy = “LRU”,
evictCount = 1,
maxObjects = 300,
objectStore = “ConcurrentStore”, //guaranteed objects
coldboxEnabled = true
},

// Register all the custom named caches you like here
caches = {
// Named cache for all coldbox event and view template caching
template = {
provider = “coldbox.system.cache.providers.CacheBoxColdBoxProvider”,
properties = {
objectDefaultTimeout = 120,
objectDefaultLastAccessTimeout = 30,
useLastAccessTimeouts = true,
freeMemoryPercentageThreshold = 0,
reapFrequency = 2,
evictionPolicy = “LRU”,
evictCount = 2,
maxObjects = 300,
objectStore = “ConcurrentSoftReferenceStore” //memory sensitive
}
},
// My new named cache!
myCache = {
provider = “coldbox.system.cache.providers.CacheBoxColdBoxProvider”,
properties = {
evictionPolicy = “LRU”,
maxObjects = 300,
objectStore = “ConcurrentSoftReferenceStore”
}
}
}
};
}

Log in DB

d5818e98-b1da-44ec-b43d-91df10c6b1f5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:10:33 DBLOG Finished reap in 9ms for CacheBoxProvider: TEMPLAT…
1afc8bc0-b866-46d4-993f-fc7552d5b61a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:24:20 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
294e18c7-9152-4ef9-95b4-c9ceae34b9ad INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:24:20 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
38a8e8a9-d045-4948-9624-c2b342043485 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:24:20 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
32c45b8b-8ec6-49da-8451-3aaf84cf8491 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:24:22 DBLOG Finished reap in 2479ms for CacheBoxProvider: MYCA…
bacdb747-c410-4b73-8d65-220828d80b6c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:24:22 DBLOG Finished reap in 2469ms for CacheBoxProvider: TEMP…
62ee0a72-9f59-4320-80ae-6a3302ee8317 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:25:16 DBLOG Finished reap in 56512ms for CacheBoxProvider: def…
3100b1a0-5a93-4cdb-b296-c1c5322e5926 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:31:56 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
378eaa8e-f6fa-4bae-9811-cab961f6ffa6 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:31:56 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
52a7efa4-c296-4a70-bb59-e9be77ef5950 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:31:56 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
23479ce3-e6e9-4a54-9bed-677558a396cc INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:34:50 DBLOG Finished reap in 174150ms for CacheBoxProvider: MY…
df93772b-8425-47f9-9fbd-303fbc231b81 INFO WMT 2014-10-28 02:34:50 DBLOG The user has now logged in.
e4a95b2a-76a0-425e-97ec-3fed41b47deb INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:34:58 DBLOG Finished reap in 182226ms for CacheBoxProvider: TE…
dd6abc5f-9eec-4c35-99a8-ceecf8a305c2 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:37:39 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
e890a4c6-ef63-4deb-a9a2-ddb17f900e8e INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:37:39 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
0c8d50ba-24df-4671-82d5-700d064953a3 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:38:31 DBLOG Finished reap in 395241ms for CacheBoxProvider: de…
39e2cb34-02d8-4a7c-b84a-7d44b99a5dcd INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:38:33 DBLOG Finished reap in 54131ms for CacheBoxProvider: TEM…
1d6145d3-cca5-41c6-9d8a-36eb87399a82 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:38:51 DBLOG Finished reap in 71733ms for CacheBoxProvider: MYC…
f978e462-cc8f-4fca-b19f-3c73cc77cb9f INFO WMT 2014-10-28 02:39:34 DBLOG The user has now logged in.
0ef8e581-1955-4d45-83f6-7f160b0e30e7 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:27 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
48aaf174-d158-4102-a9a0-78692ccec6be INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:27 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
a8541865-3a25-4344-856c-104012bf74d8 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:27 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
a844e3bc-4e0b-46a3-81f9-e467cbe3ad96 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:35 DBLOG Finished reap in 8105ms for CacheBoxProvider: MYCA…
90c63065-466c-4438-a867-28c02575223b INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:41 DBLOG Finished reap in 13739ms for CacheBoxProvider: def…
b1ed3c10-1d00-4440-9d8a-aaa7a2015d06 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:41:41 DBLOG Finished reap in 13734ms for CacheBoxProvider: TEM…
61bb1457-73d9-4dcb-9d48-a7c6648adff2 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:48:42 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
7a123a9d-c031-4f72-a571-577ed70f743e INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:48:42 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
f9b39420-28cc-45bd-8519-9a757d97928a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:48:42 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
fcbfbc06-ddab-4ad6-a530-25c66c137be5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:48:58 DBLOG Finished reap in 16697ms for CacheBoxProvider: def…
e368e128-e388-4775-932d-e83b6719e528 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:52:00 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
5476f3e8-cdf3-4457-ac39-f77dbc489ae0 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:52:40 DBLOG Finished reap in 39862ms for CacheBoxProvider: def…
1156cc2d-160f-4c28-88c3-d752fc9f3ac5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:52:42 DBLOG Finished reap in 240301ms for CacheBoxProvider: TE…
4264da6c-75e9-4fa5-9daf-baff3a76255c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 02:52:42 DBLOG Finished reap in 240303ms for CacheBoxProvider: MY…
972bb0b4-5337-4b74-919e-313804b0a3ba INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:27 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
aff49ae5-8b9e-4e93-b3e7-b435b92980ed INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:27 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
ef262458-4798-4777-83c6-2f086aae6518 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:27 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
8d2dd639-d8d6-4c74-8b16-213e2680254c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:38 DBLOG Finished reap in 11286ms for CacheBoxProvider: def…
a4b1d357-6d72-4e3c-a426-b480c000e211 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:56 DBLOG Finished reap in 28871ms for CacheBoxProvider: MYC…
e3f65a5f-f982-419f-bd23-1e7b51780ea6 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:00:56 DBLOG Finished reap in 28870ms for CacheBoxProvider: TEM…
fa440721-8b27-4569-8cae-1f756022dc7c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:10:28 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
7fdfb369-4fa2-419f-8d4c-9e209561625c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:10:29 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
8d676295-6f30-45c7-aaad-fd5cb6902e85 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:10:29 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
011f1601-3edb-411e-a1f7-db3f5a9654ae INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:11:18 DBLOG Finished reap in 49340ms for CacheBoxProvider: TEM…
1c305bb1-abdb-4810-a802-3730ea47065a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:11:18 DBLOG Finished reap in 49323ms for CacheBoxProvider: def…
388bca4a-f302-46fd-90a6-31e74f64f7c5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:11:18 DBLOG Finished reap in 4619ms for CacheBoxProvider: MYCA…
5e7313fc-bbe8-4732-bf4b-f9cef2f66bf5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:11:18 DBLOG Finished reap in 49348ms for CacheBoxProvider: MYC…
ee1ac784-5319-4896-8f0f-7cd6918b5632 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:11:18 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
a8a1d8d9-c8ba-478a-92a0-9216c4636953 INFO WMT 2014-10-28 03:12:46 DBLOG The has now logged in.
a60a70e1-f1ed-4c20-99cf-42fd647038c3 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:14:52 DBLOG Finished reap in 2146ms for CacheBoxProvider: defa…
a83245a0-fd4f-4884-8f1b-f36d107bc78c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:14:52 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
d19236e5-08be-49d9-8040-1e63521592df INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:14:52 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
f26a8086-e2da-438a-806d-a0ad3262d77f INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:14:52 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
12710869-70a0-4c49-8749-9fbc6da2bd0d INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
12e3bc35-383e-4a7e-a471-0fa326f54d73 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
446857fd-a25f-4019-b9b5-25e2aded3598 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Finished reap in 13384ms for CacheBoxProvider: def…
5adf58aa-628c-4263-b0a9-33446c8620ca INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
66642d8d-a872-4d79-8cea-faf036730c5c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Finished reap in 12098ms for CacheBoxProvider: MYC…
6719e529-573f-4ad5-aaea-e3b0e0f7cf0a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
85eb2f35-5b2d-47ee-8e5f-666cc737da7b INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Finished reap in 854ms for CacheBoxProvider: MYCAC…
9a95f03a-1684-4b1b-9b9b-53e71a57758a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Finished reap in 13386ms for CacheBoxProvider: MYC…
b0bb07d5-c74b-471d-a26e-51df57a6ce80 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:15:02 DBLOG Finished reap in 1443ms for CacheBoxProvider: MYCA…
d339ce86-1c4e-44bc-a547-13a194f05f63 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:17:19 DBLOG Finished reap in 149518ms for CacheBoxProvider: TE…
11f0c95e-8fa3-4e0a-835d-7335234df1ad INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:14 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
9a38b340-0732-4a62-99e3-8442a06628d9 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:14 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
dfdd00c6-250d-4e25-beaa-d99da651724f INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:14 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
352da0b9-992d-4967-9743-c5bf0f55cf21 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Finished reap in 26471ms for CacheBoxProvider: def…
46ccb1b3-4e0b-44b4-946d-fb796852928f INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Finished reap in 10881ms for CacheBoxProvider: TEM…
4a93d26a-4b7b-475e-9af2-0f399ba1ae07 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Finished reap in 26472ms for CacheBoxProvider: TEM…
b2e345fc-5fa7-484e-9f99-e5b5cc540497 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Finished reap in 26472ms for CacheBoxProvider: MYC…
b53d7dfc-7118-48bd-9bae-e9a83aa1ede3 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Finished reap in 10886ms for CacheBoxProvider: def…
da8bde2d-c8ce-402c-938e-9deffba10a10 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
ed73debf-1a9f-4c13-8be0-24bf49f6fa70 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:21:40 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
484dc4e9-5f83-460f-a25e-ca60a2aaaa87 INFO WMT 2014-10-28 03:22:49 DBLOG The user has now logged in.
0a839bd0-ea9a-4f7a-9b4a-abf0daac2ffb INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:28:41 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
d5ffaf69-3a87-414e-a24d-c65d0237ad2a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:28:41 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
f9bcdf30-220e-4a96-b7b4-a5100f13a118 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:28:41 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
a52d5c45-2053-4c2d-8c94-00dc26b4089c INFO WMT 2014-10-28 03:28:58 DBLOG The user has now logged in.
3b9be833-77db-47ff-93ab-7c536a2e22f0 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:31:04 DBLOG Finished reap in 143476ms for CacheBoxProvider: TE…
6709cc51-5611-4063-b6d9-30b9628684d9 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:31:04 DBLOG Finished reap in 143475ms for CacheBoxProvider: MY…
d518f43b-954a-4796-92d6-3e6545072650 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:31:04 DBLOG Finished reap in 143476ms for CacheBoxProvider: de…
4b8d05ab-dea9-4025-bcc2-40efa9253f1c INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:33:40 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
d4659864-61f5-4972-be54-5b7699a8ea81 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:35:58 DBLOG Finished reap in 137566ms for CacheBoxProvider: MY…
cdb82f4b-b91c-4bf3-9603-dcc49dfbfac8 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:42:17 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
d64fc2a6-84b6-4747-8a1d-a1d1a7282d92 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:42:17 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
f2471adb-7180-4052-9923-b251516516be INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:42:17 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
7db874e3-22a1-494c-85a4-d42ce491227d INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:42:31 DBLOG Finished reap in 14143ms for CacheBoxProvider: def…
c36f2e35-5937-456d-a045-d57a0d2e1ccd INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:42:31 DBLOG Finished reap in 14145ms for CacheBoxProvider: TEM…
10ced183-a048-4753-887d-8a59f1465052 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:43:58 DBLOG Finished reap in 100997ms for CacheBoxProvider: MY…
27f5a2c6-5d7a-4726-a3e7-ecc4d457d21e INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:44:41 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
bcfbefab-0257-49ad-a0ae-489a3fb934eb INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:44:41 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
6ab10cde-9ea4-4f96-a4df-c3a964385b2f INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:45:44 DBLOG Finished reap in 63741ms for CacheBoxProvider: def…
b88a76e6-f1c0-4b07-a474-e32015213179 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:45:52 DBLOG Finished reap in 71410ms for CacheBoxProvider: TEM…
1adff6f4-8d46-4d6e-b369-436596251490 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:58:41 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
21fc8ec8-51a9-48f3-9f8f-f756399e8551 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:58:41 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
5536a8bf-88e0-4a5d-8046-fc18d9ba6b6f INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 03:58:41 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
e64fd61b-66f1-42b4-b527-057df61a98c0 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:00:17 DBLOG Finished reap in 95907ms for CacheBoxProvider: MYC…
da0fe2c7-5060-453a-8ad1-a2a3b7aa7d85 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:00:41 DBLOG Finished reap in 120292ms for CacheBoxProvider: TE…
096aa9c5-77ef-42fd-bd10-cd30bdbc5e65 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:00:42 DBLOG Finished reap in 120584ms for CacheBoxProvider: de…
b7c3b92e-2e71-4862-b956-a9d3170c0ea9 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:02:29 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
1cff8593-dde9-4807-89a8-b30f22623c13 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:02:49 DBLOG Starting to reap CacheBoxProvider: MYCACHE, id: 20…
id severity category logdate appendername message extrainfo
364db443-cc2f-4020-b95e-b87e9d99d09a INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:02:49 DBLOG Finished reap in 20141ms for CacheBoxProvider: MYC…
8f13056b-f9a4-48a1-9c74-5ad38486d4c5 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:02:49 DBLOG Finished reap in 9127ms for CacheBoxProvider: MYCA…
18901b81-a42b-4e54-844d-7f471ee954b7 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:04:33 DBLOG Starting to reap CacheBoxProvider: TEMPLATE, id: 1…
91c893d6-70db-409e-b065-f09ace9db006 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:04:33 DBLOG Starting to reap CacheBoxProvider: default, id: 12…
410da8b8-b873-4013-abbc-1b28fec1cfcb INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:04:42 DBLOG Finished reap in 9372ms for CacheBoxProvider: TEMP…
9a961ccb-be5b-4327-949c-8c0a1d4f0c93 INFO coldbox.system.cache.providers.CacheBoxColdBoxProv… 2014-10-28 04:04:42 DBLOG Finished reap in 9394ms for CacheBoxProvider: defa…

Stack trace:

The web site you are accessing has experienced an unexpected error.
Please contact the website administrator.

The following information is meant for the website developer for debugging purposes.

Error Occurred While Processing Request

The request has exceeded the allowable time limit Tag: cfoutput

The error occurred in /var/www/coldbox/system/web/context/ExceptionBean.cfc: line 158
Called from /var/www/coldbox/system/plugins/Logger.cfc: line 124
Called from /var/www/coldbox/system/web/services/ExceptionService.cfc: line 64
Called from /var/www/coldbox/system/Coldbox.cfc: line 350
Called from /var/www/WMT_PROD/Application.cfc: line 44

156 : 		<cfif structkeyExists(instance.exceptionStruct, "TagContext") and tagContextLength>
157 : 			<cfloop from="1" to="#tagContextLength#" index="i">
**158 : 			  <cfsavecontent variable="entry"><cfoutput>ID: <cfif not structKeyExists(arrayTagContext[i], "ID")>N/A<cfelse>#arrayTagContext[i].ID#</cfif>; LINE: #arrayTagContext[i].LINE#; TEMPLATE: #arrayTagContext[i].Template# #chr(13)#</cfoutput></cfsavecontent>**
159 : 			  <cfset rtnString = rtnString & entry>
160 : 			</cfloop>
2

Do you have Fusion Reactor installed on the machine? How many requests are running and what are they doing (stack trace).

There is also a good chance the issue is outside of CF. Look at any of the following that may run at that time of night:

  • CF scheduled tasks
  • Bots hitting your site
  • anti-virus scans on CF or DB server
  • DB maintenance plans (re-indexing, etc)
  • DB backups
  • VM image backups
  • file backups
  • Hard disk defrag
  • Anything that could create large amount of disk IOPS or network bandwidth
    Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

3

Thanks Brad,

Here is what I have found out:

There is also a good chance the issue is outside of CF. Look at any of the following that may run at that time of night:

  • CF scheduled tasks - Only one scheduled task is being run at 12:00am - Simple requests to fire off an update query
  • Bots hitting your site - This is an internal site so no bots allowed. They are shot at the gate.
  • anti-virus scans on CF or DB server - Possible I will check to see if anything is running.
  • DB maintenance plans (re-indexing, etc) - Possible I will check to see if anything is running.
  • DB backups - Possible I will check to see if anything is running.
  • VM image backups - This is what I think might be causing the issues. I’m also investigating this to see what time the image is being backed up each night.
  • file backups - I don’t think there are any file backups.
  • Hard disk defrag - I don’t think that this is running.
  • Anything that could create large amount of disk IOPS or network bandwidth - This is also possible the client is not stateside so this could be an issue.
    Thanks for looking into this. I’ll report back once I have some answers but if you have anything else I should try or ask I’ll be glad to do it.

Thanks

4

Update:

So, the network group replied that during this time frame in question, the PC is swapping a lot during that time. They recommended increasing the memory from 4G. Any suggestions on what to bump it to? Most would say 8G but it’s its better to go to 16G now it the time to do it.

Thanks

5

I would be more inclined to run some profiling, to figure out what is causing something to use 4GB of ram.

6

Thanks Andrew, do you have any suggestions on what to run? This report is being conducted by a 3rd party. I would love to give them some suggestions and try to figure out what is causing the slow down.

7

What Brad suggested, Fusion Reactor can profile your site and see what is taking so long. I would say if your pages are taking that long to run, there can be some serious optimizations to be made.

8

Thanks. I’ll see if I can get permission to run it and analyze some of the logs to see where the problem is. Thanks

9

Can you clarify what you mean by swapping? Do you mean hitting the swap file as in something is using all the RAM? Also, there is a difference between “swapping a lot” and “spending a lot of time swapping”. The former implies large IOPS, the latter could just be high latencies.

As long as your Java heap is not larger than the amount of physical RAM on the machine plus whatever the OS needs and any other running programs, CF might not be the issue. Start by simply looking at the list of running processes on the machine during that timeframe at an OS level. Any operation that loads a large amount of data into memory could cause this including anti-virus scans or backups.

Also, if you are using a SAN, remember you might be sharing physical spindles with completely different servers. Use perfmon to check your disk queue lengths, latencies, and IOPS. There are entire articles written just about that, but a general rule of thumb can be that latencies of 5-10ms or less are acceptable. Anything up to 50ms is ok, and over is getting unacceptable. Latencies spiking could indicate the underlying disk subsystem is being saturated either by your VM, or others that share it. Of course, those same numbers apply to local drives as well, you can just rule out the possibility of other VMs using your disks.

If you “network team” manages the OS and hardware, this seems like a bit of lazy reporting from them.

You’ll note I didn’t answer your question about adding RAM because I think you should actually find the bottleneck before just throwing more hardware at it. Besides, the JVM is capped on how much RAM it can use, so can’t really “use up” all your machine’s RAM, it can just cause a lot of garbage collections.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

10

“You’ll note I didn’t answer your question about adding RAM because I think you should actually find the bottleneck before just throwing more hardware at it. Besides, the JVM is capped on how much RAM it can use, so can’t really “use up” all your machine’s RAM, it can just cause a lot of garbage collections.”

Developer,

We need to identify this bottleneck.

Manager,

How long will that take?

Developer,

Maybe a whole sprint, as we would like to clean up some technical debt while were in there.

Manager,

No, we will miss our deadline add more ram.

11

Lol, that sounds like a Dilbert cartoon. I’m sorry if you work for a short-sighted pointy hair. If the developers don’t have the bandwidth to look at server performance and your company doesn’t employ someone to manage the servers, your next recourse is to contract someone who can help. Ortus offers server tuning and consulting.

http://www.ortussolutions.com/#services

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

12

Update:

BTW - The description was just about on point with what is going on. I did check and ask the network group if anything was going on. They quickly dismissed the issue as “nothing” was running. We asked the DBA’s the same question and they gave the same answer. Later on we got a "Oh sorry, looks like there was a backup script that had a “bug” in it and it was taking 2 hours to run. We are still investigating to see if that is the issue. I also have not installed fusion reactor either.

I do appreciate the suggestions about things to check for on the virtual server and while information is very slow it is eventually making it’s way to me.

I’m sure I’ll have another update next week about something or the other.