[imp] New IMAP server, troubleshooting slow IMP performance

[Simon Wilson]

>>> I just switched it to nosql to use the mongo nosql setup on the  
>>> server that is used for Horde cache - and the email times have  
>>> dropped to about 0.5s.
>>>
>>> Thanks Jan, that was the ticket. I think nosql is probably better  
>>> performance anyway?
>>
>> Probably yes.
>>
>> --
>> Jan Schneider
>
> Since setting my IMAP cache to be nosql (mongo), every 5 or 6 hours  
> mongo goes 100% CPU for 2 or 3 hours. The mongod log is a constant  
> flow of messages, as follows below.
>
> During this time, Imp seems to be slower again, like when IMAP  
> caching was not working properly.
>
> Then for some reason it will just stop. The log sequence shows the  
> tail of it running flat out (triggering every 50 - 100ms), then  
> stopping.
>
> Any ideas?
>
> Simon
>
> 2017-08-01T23:04:13.836+1000 I COMMAND  [conn100] query  
> horde.horde_cache query: { cid: "e471c4112fbd3a7374d6deaa2192039e" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59189  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:463  
> nreturned:1 reslen:605 locks:{ Global: { acquireCount: { r: 928 } },  
> Database: { acquireCount: { r: 464 } }, Collection: { acquireCount:  
> { r: 464 } } } 133ms
> 2017-08-01T23:04:13.943+1000 I COMMAND  [conn101] query  
> horde.horde_cache query: { cid: "4c3e501b437e318e40097fe327d66ea6" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59180  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:464  
> nreturned:1 reslen:322 locks:{ Global: { acquireCount: { r: 930 } },  
> Database: { acquireCount: { r: 465 } }, Collection: { acquireCount:  
> { r: 465 } } } 123ms
> 2017-08-01T23:04:14.024+1000 I COMMAND  [conn100] query  
> horde.horde_cache query: { cid: "e471c4112fbd3a7374d6deaa2192039e" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59189  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:464  
> nreturned:1 reslen:605 locks:{ Global: { acquireCount: { r: 930 } },  
> Database: { acquireCount: { r: 465 } }, Collection: { acquireCount:  
> { r: 465 } } } 173ms
> 2017-08-01T23:04:14.050+1000 I COMMAND  [conn73] query  
> horde.horde_cache query: { cid: "0a6536c57d01c2ea148c511301648064" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59182  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:463  
> nreturned:1 reslen:765 locks:{ Global: { acquireCount: { r: 928 } },  
> Database: { acquireCount: { r: 464 } }, Collection: { acquireCount:  
> { r: 464 } } } 160ms
> 2017-08-01T23:04:15.010+1000 I COMMAND  [conn73] query  
> horde.horde_cache query: { cid: "7f626b12cffb4951d3f569c6d2f0d3cd" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59184  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:463  
> nreturned:1 reslen:736 locks:{ Global: { acquireCount: { r: 928 } },  
> Database: { acquireCount: { r: 464 } }, Collection: { acquireCount:  
> { r: 464 } } } 101ms
> 2017-08-01T23:04:15.248+1000 I COMMAND  [conn101] query  
> horde.horde_cache query: { cid: "f73608d48bef65a48f2a887a510b397b" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59183  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:463  
> nreturned:1 reslen:701 locks:{ Global: { acquireCount: { r: 928 } },  
> Database: { acquireCount: { r: 464 } }, Collection: { acquireCount:  
> { r: 464 } } } 106ms
> 2017-08-01T23:04:30.409+1000 I NETWORK  [conn95] end connection  
> 127.0.0.1:47564 (26 connections now open)
> 2017-08-01T23:04:35.415+1000 I NETWORK  [conn49] end connection  
> 127.0.0.1:40664 (25 connections now open)
> 2017-08-01T23:04:37.417+1000 I NETWORK  [conn99] end connection  
> 127.0.0.1:56114 (24 connections now open)
> 2017-08-01T23:04:39.419+1000 I NETWORK  [conn64] end connection  
> 127.0.0.1:42526 (23 connections now open)
> 2017-08-01T23:04:43.423+1000 I NETWORK  [conn92] end connection  
> 127.0.0.1:47472 (22 connections now open)
> 2017-08-01T23:04:47.427+1000 I NETWORK  [conn78] end connection  
> 127.0.0.1:44930 (21 connections now open)
> 2017-08-01T23:04:51.432+1000 I NETWORK  [conn86] end connection  
> 127.0.0.1:45858 (20 connections now open)
> 2017-08-01T23:04:56.434+1000 I NETWORK  [conn83] end connection  
> 127.0.0.1:45694 (19 connections now open)
> 2017-08-01T23:05:08.004+1000 I COMMAND  [conn74] query  
> horde.horde_cache query: { cid: "cae0be8ca4bcc7fe642c2498640c0af4" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59188  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:463  
> nreturned:1 reslen:440 locks:{ Global: { acquireCount: { r: 928 } },  
> Database: { acquireCount: { r: 464 } }, Collection: { acquireCount:  
> { r: 464 } } } 106ms
> 2017-08-01T23:05:08.232+1000 I COMMAND  [conn91] query  
> horde.horde_cache query: { cid: "7f626b12cffb4951d3f569c6d2f0d3cd" }  
> planSummary: COLLSCAN ntoskip:0 keysExamined:0 docsExamined:59184  
> cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:464  
> nreturned:1 reslen:736 locks:{ Global: { acquireCount: { r: 930 } },  
> Database: { acquireCount: { r: 465 } }, Collection: { acquireCount:  
> { r: 465 } } } 102ms
> 2017-08-01T23:05:33.484+1000 I NETWORK  [conn97] end connection  
> 127.0.0.1:56032 (18 connections now open)
>
> --
> Simon Wilson
> M: 0400 12 11 16

Mongo ran at 100% CPU with Imp IMAP caching for about 7 hours straight  
overnight. 

I have set Imp to use Redis (hashtable) cache, will see if that works better.

Simon

-- 
Simon Wilson
M: 0400 12 11 16