[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