Windows messages are lost when using SetTimer

[Clément 148]

Hi,

 

I'm using Delphi Rio.

I have this thread that respond to Windows Messages using PostThreadMessage called from the main thread or any other thread. It is fast and working fine.

 

procedure TdhsLoggerThread.Execute;
var
  lMsg : TMsg;
  lCOunt : Integer;
begin
  inherited;
  fLogs := TObjectDictionary<String,TdhsLoggerItemData>.Create([doOwnsValues]);
  try
    gLoggerThreadID := ThreadID;
    PeekMessage( lMsg, 0 , WM_USER , WM_USER , PM_NOREMOVE );
    //FTimerID := SetTimer(0,0,1000,nil); #1
    lCount := 0;
    while GetMessage( lMsg, 0, 0 , 0 ) do begin
       inc(lCount);
       DoProcessMessages( lMsg );
       // if (lCOunt mod 1000) = 0 then  #2
       //    DoFlushLogs;                #2
    end;

   // KillTimer(0,FTimerID); #1

    DoFlushLogs;

  finally
    fLogs.Free;
  end;

end;

If I run the code as posted ( commenting #1 & #2), during my stress test with 200000 calls, lCount shows the correct number of processed messages (200005).
I need to FlushLogs every second, so I added the code I marked with #1, I'm receiving WM_TIMER messages, but some of my messages are lost and lCount shows 195453 calls ( The count varies but I usually losing between 5000 to 10000 messages) .
Every message has information I can't loose, so missing messages is a big no no!

If I comment #1 and uncomment #2 I get all the calls as expected. No problems with DoFlushLogs then, so I'm messing up SetTimer call or it is not supposed to be called the I'm calling it.

 

Am I using correctly SetTimer?

I'm trying to avoid creating another thread just to control the timer, is there another way create a timer in the same thread without loosing my messages? ( I don't want to use Sleep() ).
All I need is to timely flushlogs. If there's no other way, I will create a ThreadedTimer.

 

TIA,

Clément
 

 

 

[David Heffernan 2345]

A complete repro is probably necessary here. A timer seems needless. Just keep track of the time when you last flushed and do it again once a second has elapsed. 

 

[PeterBelow 238]

Timer messages have low priority. If your DoProcessMessages call takes longer than the message interval then a timer tick will not add a new wm_timer message to the queue but increment an internal count for the message already in the queue.

Use a waitable timer and one of the MsgWait API functions instead of SetTimer,

[Clément 148]

10 hours ago, David Heffernan said:

A complete repro is probably necessary here. A timer seems needless. Just keep track of the time when you last flushed and do it again once a second has elapsed. 

 

If I don't use timers I will have to depend on messages to flush. So I might end up with a lot of "unflushed" log. I would depend on the client to call a "flush logs", that would be wrong.

[Clément 148]

3 hours ago, PeterBelow said:

Timer messages have low priority. If your DoProcessMessages call takes longer than the message interval then a timer tick will not add a new wm_timer message to the queue but increment an internal count for the message already in the queue.

Use a waitable timer and one of the MsgWait API functions instead of SetTimer,

That seems to be the way to go. I avoided using it in the beginning because  MsgWaitForMultipleObjectsEx handles a lot more messages and events than I actually need. But there's this parameters in the documentation where I can set QS_TIMER or QS_POSTMESSAGE that might do the trick! 

Thanks

[David Heffernan 2345]

35 minutes ago, Clément said:

If I don't use timers I will have to depend on messages to flush. So I might end up with a lot of "unflushed" log. I would depend on the client to call a "flush logs", that would be wrong.

No you won't. There are plenty of timer free solutions I would expect. Very hard to give advice without context. And very hard to explain why messages are missing with only a partial extract of code.

 

Anyway, good luck. 

[Lars Fosdal 1792]

I use a queue,  Each thread writes log data to the queue which basically is a ring buffer. The log thread periodically (every two seconds) flush the data asynchronously from the ring buffer, writing multiple entries at a time.

I really don't like relying on messages for inter-thread communication - with one exception: the background threads notifying the foreground thread that there is data to fetch from the thread out-queues.

[Clément 148]

On 9/16/2019 at 2:19 PM, David Heffernan said:

No you won't. There are plenty of timer free solutions I would expect. Very hard to give advice without context. And very hard to explain why messages are missing with only a partial extract of code.

 

Anyway, good luck. 

I'm not at the office right now, but the main code is very similar to the one below:

procedure Tform1.OnButton1Click( Sender : Tobject );
var
  lLog : IdhsLogger;
begin
  lLog := TdhsLogger.Create('Test', TdhsLoggerWriterFileStream.Create( ExtractFilePath( ParamStr(0) ) ) );
  for i := 0 to 200 * 1000 do
     lLog.WriteFMT('Logging test %d',[i]);
     
end;

lLog will postThreadmessages to TdhsLoggerThread ( the code I posted above ). Just by commenting the lines I got the results I wrote.
When all goes well , the log file must end with:
200000: 20190917 17:02:00.999   Logging test 200000

The first number ( 200000 ) is the editors ( notepad++) line number. It must match the logging test message number.

 

When I use SetTimer, the log ends showing:

195432: 20190917 17:02:00.999   Logging test 200000

 

The writing is synchronized up to 60.000 or 70.000 entries than 5.000 to 10.000 Logging test are missing. 

 

In my new implementation I'm using MsgWaitForMultipleObjects and all 200.000 logs entries are displayed. I changed my stress test to 500.000 logs entries and then to 1.000.000 log entries. The log file ended up as expected (The editor's 500000th line shows "Logging test 500000" and the 1000000th line shows "Logging test 1000000". I will revisit the implementation using SetTimer to compare the differences.

 

Anyway MsgWaitForMultipleObjects has a 1s timeout that flushes the logs just like SetTimer triggering WM_TIMER. The exact same stress test. The classes and method calls are the same in both implementation. The only difference is how I'm dealing with the TIMEOUT.

 

 

 

[David Heffernan 2345]

Timers are for GUIs. MsgWaitForMultipleObjects is one sound way to implement a message pump on a thread that needs to do tasks periodically. 

[Clément 148]

17 hours ago, Lars Fosdal said:

I use a queue,  Each thread writes log data to the queue which basically is a ring buffer. The log thread periodically (every two seconds) flush the data asynchronously from the ring buffer, writing multiple entries at a time.

I really don't like relying on messages for inter-thread communication - with one exception: the background threads notifying the foreground thread that there is data to fetch from the thread out-queues.

I'm using a queue also. I'm passing data from client-part log to the thread part via PostThreadMessages. I trust windows messaging and atomic operations to avoid using Critical sections. Also I making sure that all objects allocated in the client-part context are released in the client-part. 
I have to deal with a small bug, but I believe that very soon I will start stress testing with multi-threads  and hopefully I won't mess my installation (to much  )

[Clément 148]

3 minutes ago, David Heffernan said:

Timers are for GUIs. MsgWaitForMultipleObjects is one sound way to implement a message pump on a thread that needs to do tasks periodically. 

Googling around I found that WaitForMultipleObjects might be a better candidate since the LoggerThread will never deal with GUI messaging, and will most probably be working in a Windows Service. I wrote my message pumping using WaitForMultipleObjects but it's not working. That's the bug I'm dealing with. But as I have MsgMsgWaitForMultipleObjects working, I won't waste more than an hour figuring out what's wrong. I need to start Multi-thread test.

[Fr0sT.Brutal 900]

@Clément you forgot to wait for message queue to init - there's a time lag after PeekMessage is called until the thread is really ready to handle messages so if you post a message right after a thread is created, it will fail

I use the following code

procedure TMsgLoopThread.Execute; 
  ...
  PeekMessage(MsgRec, 0, WM_USER, WM_USER, PM_NOREMOVE);
  SetEvent(FEvMsgQueueReady);
  ...

function TMsgLoopThread.WaitStart(WaitInterval: DWORD): DWORD;
begin
  Result := WaitForSingleObject(FEvMsgQueueReady, WaitInterval);
end;

and call WaitStart after I create the thread

[Clément 148]

9 hours ago, Fr0sT.Brutal said:

@Clément you forgot to wait for message queue to init - there's a time lag after PeekMessage is called until the thread is really ready to handle messages so if you post a message right after a thread is created, it will fail

I use the following code

procedure TMsgLoopThread.Execute; 
  ...
  PeekMessage(MsgRec, 0, WM_USER, WM_USER, PM_NOREMOVE);
  SetEvent(FEvMsgQueueReady);
  ...

function TMsgLoopThread.WaitStart(WaitInterval: DWORD): DWORD;
begin
  Result := WaitForSingleObject(FEvMsgQueueReady, WaitInterval);
end;

and call WaitStart after I create the thread

@Fr0sT.Brutal thanks for the tip. Unfortunately I made a very stupid mistake. During my tests I generated over 1.000.000 posts and of course I was NOT checking the post result. Messages where stacking faster than they would be processed. 
Anyway, I had to redesign.  To make a long story short, the routine is almost 20x faster than logging directly to a file . 

 

[David Heffernan 2345]

 

1 hour ago, Clément said:

Unfortunately I made a very stupid mistake. During my tests I generated over 1.000.000 posts and of course I was NOT checking the post result. Messages where stacking faster than they would be processed.

This is why you should make a repro. Worth bearing that in mind for the future. 

[Clément 148]

1 hour ago, David Heffernan said:

 

This is why you should make a repro. Worth bearing that in mind for the future. 

When I found the mistake I picture your ghostbuster sign with a " I told you so " message. 
Anyway, there were a lot of things to consider. I had to redesign the solution since I will have to deal with slow medias and the message queue in windows has room for 10000 messages. 
This is why I like this forum, it keeps me less stupid. Thanks for the heads up!

[Fr0sT.Brutal 900]

Yes, you should always check result of PostMessage especially if you post some allocated memory, otherwise you'll get mem leak.

 

Btw, in my app I randomly face an issue with message threads - I have 3 of them and when one is delayed, in some cases PostThreadMessage starts returning NOT_ENOUGH_QUOTA though I limit queue size by 3000 messages for each thread. Seems to me the 10k limit is not per-thread as MSDN says but per-process or some undocumented per-process limit exists too.

[Clément 148]

8 hours ago, Fr0sT.Brutal said:

Yes, you should always check result of PostMessage especially if you post some allocated memory, otherwise you'll get mem leak.

 

Btw, in my app I randomly face an issue with message threads - I have 3 of them and when one is delayed, in some cases PostThreadMessage starts returning NOT_ENOUGH_QUOTA though I limit queue size by 3000 messages for each thread. Seems to me the 10k limit is not per-thread as MSDN says but per-process or some undocumented per-process limit exists too.

This is what I suspected too. I managed to track every message I sent to the thread and it broke at 5k messages, the process managed to write 2k logs before going bananas.
In this new design,  I'm using fewer messages. One to register the Logger and One to unregister it.