Back to Community Threads
3
MailService.exe high memory usage
Problem reported by Mark Thornton - 2/24/2023 at 12:46 PM
Submitted
I'm running running Build 8451 that I upgraded to on Tuesday, February 21. Today my mail server became very sluggish, crashing desktop clients, etc. I logged into the mail server itself and found the mailservice.exe process had consumed all 20 GB of available memory. I stopped the service then restarted it and am watching the memory climb up to 8 GB and now seems to be leveling off there. Where should I look in the logs to determine what was consuming all the memory?

8 Replies

Reply to Thread
0
Gabriele Maoret - SERSIS Replied
2/24/2023 at 9:25 PM
I'm seeing similar memory issues in SmarterMail after update to Build 8451.

Maybe can this be a bug in this build?
Gabriele Maoret - Head of SysAdmins at SERSIS
Currently manages 3 SmarterMail installations (1 in cloud for SERSIS which provides service to a few hundreds 3rd party Mail Domains + 2 on premise to customers)
0
Mark Thornton Replied
2/26/2023 at 12:30 PM
I'm checking back in on my server and it has been running between 6 and 8 GB of RAM used by mailserver.exe since I restarted the service. Still don't know what sent it over the edge before.
0
mh Replied
3/2/2023 at 1:13 PM
8251, same issues in the past few weeks. Either related to a search bug (seems to happen possibly after a global search rather than just a specific folder) or a windows update is causing issues somewhere. Doesn't happen often, but it will climb and client connections will time out
0
Kyle Kerst Replied
3/2/2023 at 3:40 PM
Employee Post
Do any of you have anything being reported with exception in the log entry under the Error or protocol logs? 
Kyle Kerst
Technical Support Specialist
SmarterTools Inc.
(877) 357-6278
www.smartertools.com
0
mh Replied
3/3/2023 at 9:21 AM
This was at the time (~2:30-2:53pm was the issue) that the service had just been restarted in Administrative logs, all for the same user -

[2023.03.02] 14:53:00.699 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070048] [DisplayName: 2422385f-f9fc-4896-be61-666b69cf7307] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.699 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070049] [DisplayName: 8bc085ba-2835-4606-8bdc-55612bf73782] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.720 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070048] [DisplayName: 2422385f-f9fc-4896-be61-666b69cf7307] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.720 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070049] [DisplayName: 8bc085ba-2835-4606-8bdc-55612bf73782] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.732 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070048] [DisplayName: 2422385f-f9fc-4896-be61-666b69cf7307] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.732 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070049] [DisplayName: 8bc085ba-2835-4606-8bdc-55612bf73782] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.732 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070048] [DisplayName: 2422385f-f9fc-4896-be61-666b69cf7307] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
[2023.03.02] 14:53:00.732 [Folder Delete:SearchFolder] [User: ---] [FolderId: 2070049] [DisplayName: 8bc085ba-2835-4606-8bdc-55612bf73782] Stack:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
[2023.03.02]    at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
Nothing in the "Error" log file

In the IMAP log, around this time -
[2023.03.02] 14:28:55.223 [x.x.x.x][34126772] response: * OK IMAP 
[2023.03.02] 14:28:55.223 [x.x.x.x][34126772] connected at 3/2/2023 2:28:55 PM
[2023.03.02] 14:28:56.051 [x.x.x.x][34126772] command: 1 CAPABILITY
[2023.03.02] 14:28:56.051 [x.x.x.x][34126772] response: * CAPABILITY IMAP4rev1 AUTH=CRAM-MD5 AUTH=PLAIN SASL-IR UIDPLUS QUOTA XLIST CHILDREN ENABLE CONDSTORE IDLE STARTTLS
[2023.03.02] 14:28:56.051 [x.x.x.x][34126772] response: 1 OK CAPABILITY completed
[2023.03.02] 14:28:56.285 [x.x.x.x][34126772] command: 2 AUTHENTICATE PLAIN
[2023.03.02] 14:28:56.285 [x.x.x.x][34126772] response: +
[2023.03.02] 14:28:56.348 [x.x.x.x][34126772] PLAIN message received AGxlYXN0QGZvbW50dC5jb20ATGluZHNleTkx
[2023.03.02] 14:28:56.348 [x.x.x.x][34126772] response: 2 OK PLAIN authentication successful
[2023.03.02] 14:28:56.348 [x.x.x.x][34126772] redacted@domain.com logged in
[2023.03.02] 14:28:56.426 [x.x.x.x][34126772] command: 3 CAPABILITY
[2023.03.02] 14:28:56.426 [x.x.x.x][34126772] response: * CAPABILITY IMAP4rev1 AUTH=CRAM-MD5 AUTH=PLAIN SASL-IR UIDPLUS QUOTA XLIST CHILDREN ENABLE CONDSTORE IDLE STARTTLS
[2023.03.02] 14:28:56.426 [x.x.x.x][34126772] response: 3 OK CAPABILITY completed
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] command: 4 SELECT INBOX
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * 1438 EXISTS
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * 140 RECENT
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * OK [UNSEEN 1423] Message 1423 is first unseen
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * OK [UIDVALIDITY 1] UIDs valid
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * OK [UIDNEXT 9409] Predicted next UID
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft \Recent)
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \Recent)] Folder flags
[2023.03.02] 14:28:56.551 [x.x.x.x][34126772] response: 4 OK [READ-WRITE] SELECT completed
[2023.03.02] 14:28:56.707 [x.x.x.x][34126772] command: 5 UID FETCH 9396 BODY.PEEK[2]
[2023.03.02] 14:31:15.375 [x.x.x.x][34126772] response: 5 OK FETCH completed.
[2023.03.02] 14:31:15.375 [x.x.x.x][34126772] Exception: (PooledTcpItem.cs) An established connection was aborted by the software in your host machine
[2023.03.02] 14:31:15.563 [x.x.x.x][34126772] StackTrace:    at System.Net.Sockets.Socket.BeginReceive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
In the MAPI log -
[2023.03.02] 11:12:38.901 [{7BAB4169-1E04-4A8F-A737-286901F89B64}:848] Exception: System.NullReferenceException: Object reference not set to an instance of an object.
[2023.03.02] 11:13:15.456 [{4C27D1AC-9A26-4547-ADCF-426576886389}:28] Exception: System.NullReferenceException: Object reference not set to an instance of an object.
[2023.03.02] 11:43:34.028 [{396570E5-950A-4FF9-A800-38DE904973ED}:30] Exception: System.Exception: Array copy with negative number -2081 [sizeOfCurrentItem] 34 - 2115
[2023.03.02] 11:43:34.043 [{380084D2-B0EE-428E-B7BD-C90750CC97C0}:15] Exception: System.Exception: Array copy with negative number -5825 [sizeOfCurrentItem] 34 - 5859
[2023.03.02] 12:23:11.784 [{F16A5267-9685-4F3F-8BED-E6D5AD7188F6}:15] Exception: System.NullReferenceException: Object reference not set to an instance of an object.
[2023.03.02] 13:08:05.680 [{253BE6F5-6ABB-45DB-8266-6F02BA965DFA}:15] Exception: System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
[2023.03.02]    at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
SMTP Log around this time or hour before -

[2023.03.02] 13:48:11.107 [x.x.x.x][8455836] rsp: 220 x.x.com
[2023.03.02] 13:48:11.107 [x.x.x.x][8455836] connected at 3/2/2023 1:48:11 PM
[2023.03.02] 13:48:11.107 [x.x.x.x][8455836] Country code: US
[2023.03.02] 13:48:11.154 [x.x.x.x][8455836] cmd: EHLO Membership2PC
[2023.03.02] 13:48:11.154 [x.x.x.x][8455836] rsp: 250-x.x.com Hello [x.x.x.x]250-SIZE 139810133250-AUTH LOGIN CRAM-MD5250-STARTTLS250-8BITMIME250-DSN250 OK
[2023.03.02] 13:48:11.200 [x.x.x.x][8455836] cmd: STARTTLS
[2023.03.02] 13:48:11.200 [x.x.x.x][8455836] rsp: 220 Start TLS negotiation
[2023.03.02] 13:48:11.372 [x.x.x.x][8455836] cmd: EHLO Membership2PC
[2023.03.02] 13:48:11.372 [x.x.x.x][8455836] rsp: 250-x.x.com Hello [x.x.x.x]250-SIZE 139810133250-AUTH LOGIN CRAM-MD5250-8BITMIME250-DSN250 OK
[2023.03.02] 13:48:11.419 [x.x.x.x][8455836] cmd: AUTH LOGIN
[2023.03.02] 13:48:11.419 [x.x.x.x][8455836] rsp: 334 VXNlcm5hbWU6
[2023.03.02] 13:48:11.466 [x.x.x.x][8455836] Authenticating as email@domain.com
[2023.03.02] 13:48:11.466 [x.x.x.x][8455836] rsp: 334 UGFzc3dvcmQ6
[2023.03.02] 13:48:11.779 [x.x.x.x][8455836] rsp: 235 Authentication successful
[2023.03.02] 13:48:11.794 [x.x.x.x][8455836] Authenticated as email@domain.com
[2023.03.02] 13:48:11.841 [x.x.x.x][8455836] cmd: MAIL FROM: <email@domain.com>
[2023.03.02] 13:48:11.841 [x.x.x.x][8455836] senderEmail(1): email@domain.com parsed using: <email@domain.com>
[2023.03.02] 13:48:11.841 [x.x.x.x][8455836] rsp: 250 OK <email@domain.com> Sender ok
[2023.03.02] 13:48:11.841 [x.x.x.x][8455836] Sender accepted. Weight: 0. Block threshold: 25. 
[2023.03.02] 13:48:11.888 [x.x.x.x][8455836] cmd: RCPT TO: <email@domain.org>
[2023.03.02] 13:48:11.888 [x.x.x.x][8455836] rsp: 250 OK <email@domain.org> Recipient ok
[2023.03.02] 13:48:11.919 [x.x.x.x][8455836] cmd: DATA
[2023.03.02] 13:48:11.919 [x.x.x.x][8455836] Performing PTR host name lookup for x.x.x.x
[2023.03.02] 13:48:11.919 [x.x.x.x][8455836] PTR host name for x.x.x.x resolved as static-23-244-80-219.oh.x.x.net
[2023.03.02] 13:48:11.935 [x.x.x.x][8455836] rsp: 354 Start mail input; end with <CRLF>.<CRLF>
[2023.03.02] 13:48:12.029 [x.x.x.x][8455836] senderEmail(2): email@domain.com parsed using: <email@domain.com>
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] rsp: 250 OK
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] Client socket is disconnected! Disconnect exception encountered: False, IsDisconnected: True, This message will be rejected.
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] Received message size: 54049 bytes
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] Successfully wrote to the HDR file. (c:\SmarterMail\Spool\SubSpool2\511769714188.hdr)
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] Data transfer succeeded, writing mail to 511769714188.eml (MessageID: <008d01d94d37$8a087390$9e195ab0$@x.org>)
[2023.03.02] 13:52:45.250 [x.x.x.x][8455836] disconnected at 3/2/2023 1:52:45 PM

[2023.03.02] 13:58:52.116 [x.x.x.x][35989911] rsp: 220 x.x.com
[2023.03.02] 13:58:52.116 [x.x.x.x][35989911] connected at 3/2/2023 1:58:52 PM
[2023.03.02] 13:58:52.116 [x.x.x.x][35989911] Country code: US
[2023.03.02] 13:58:52.179 [x.x.x.x][35989911] cmd: EHLO localhost.localdomain
[2023.03.02] 13:58:52.179 [x.x.x.x][35989911] rsp: 250-x.x.com [x.x.x.x]250-SIZE 139810133250-AUTH LOGIN CRAM-MD5250-STARTTLS250-8BITMIME250-DSN250 OK
[2023.03.02] 13:58:52.241 [x.x.x.x][35989911] cmd: STARTTLS
[2023.03.02] 13:58:52.241 [x.x.x.x][35989911] rsp: 220 Start TLS negotiation
[2023.03.02] 13:58:52.288 [x.x.x.x][35989911] rsp: 554 Security failure
[2023.03.02] 13:58:52.288 [x.x.x.x][35989911] Exception negotiating TLS session: The secure connection has failed due to an unsupported protocol such as TLS 1.0 or SSL 3.0. A call to SSPI failed, see inner exception..
[2023.03.02] 13:58:52.304 [x.x.x.x][35989911] disconnected at 3/2/2023 1:58:52 PM


[2023.03.02] 14:35:27.062 [x.x.x.x][64639041] rsp: 220 x.x.com
[2023.03.02] 14:35:27.062 [x.x.x.x][64639041] connected at 3/2/2023 2:35:27 PM
[2023.03.02] 14:35:27.062 [x.x.x.x][64639041] Country code: HK
[2023.03.02] 14:35:28.843 [x.x.x.x][64639041] Exception: (PooledTcpItem.cs) An established connection was aborted by the software in your host machine
[2023.03.02] 14:35:30.406 [x.x.x.x][64639041] StackTrace:    at System.Net.Sockets.Socket.BeginReceive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
0
Kyle Kerst Replied
3/6/2023 at 9:03 AM
Employee Post
It looks like one of the messages in that user's account is tripping things up. Anything abnormal about the messages in their Inbox? The other error is a pretty standard TLS handshake error, and usually means their client and your server couldn't agree on a TLS version (they have incompatible versions available.) If the user updates that client, and you run the latest Windows Updates and TLS versions on the server; you should be in good shape!
Kyle Kerst
Technical Support Specialist
SmarterTools Inc.
(877) 357-6278
www.smartertools.com
0
JerseyConnect Team Replied
3/13/2023 at 12:36 PM
For those of you on 8451, are you still having memory consumption issues or has it stabilized?
2
Mark Thornton Replied
3/13/2023 at 2:03 PM
I haven't had a repeat of the issue on my server. It has been stable under 8 out of 20 GB since I restarted the server. I suspect it was a bad message that the system couldn't let go of. That used to be a big problem back in the early days of the internet. I remember having to manually edit user mailboxes to cut out messages that wouldn't go through the system.
Back to Community Threads

Reply to Thread

Related Knowledge Base Articles

SmarterMail Server Performance TuningSmarterMail > Server Configuration and Management
Configure Perfmon to capture Disk IO activity and potential Disk Issues.SmarterMail > Troubleshooting
Flex Billing for Microsoft Exchange ActiveSyncSmarterMail > Desktop and Mobile Synchronization
Explanation of Exchange ActiveSync Push FunctionalitySmarterMail > Desktop and Mobile Synchronization
Increase the Total Number of Emails Allowed in the SpoolSmarterMail > Installation and Configuration