Can you work the other way? Create a simple project with your thread, see if it sleep or not, then add things until it stops sleeping.
Weird problems sometimes are fixed by removing the not working control/class and add it again.
I hope you find the problem soon.
Have you checked for another thread sleep command as I think that would override your 15 second sleep.
Ding Ding Ding! I have a 100ms sleep in the UserInterface update. When I commented that line out, suddenly the 15 second sleep started working… sort of.
'Logstring = "Pausing 15 seconds for Prinect processing" _
'+ EndOfLine + "—————————————————————————————————————————————————————————————————————————————————————"
'Me.AddUserInterfaceUpdate("Transaction":Logstring)
'Me.Sleep(15000,False)
static traceLabel As Integer
traceLabel = traceLabel + 1
// log a message and current time
Var dt As DateTime = DateTime.Now
System.DebugLog(dt.SQLDateTime + " trace start 15secs #"+traceLabel.ToString)
Me.Sleep(15000,False)
dt = DateTime.Now
System.DebugLog(dt.SQLDateTime + " trace end 15secs #"+traceLabel.ToString)
Resulted in these times each pause being 15 seconds:
1:16:30 PM : PrinectUpdateXJDF.exe Launched
1:17:34 PM : 2024-03-05 13:17:34 trace start 15secs #1
1:17:49 PM : 2024-03-05 13:17:49 trace end 15secs #1
1:17:52 PM : 2024-03-05 13:17:52 trace start 15secs #2
1:18:07 PM : 2024-03-05 13:18:07 trace end 15secs #2
1:18:10 PM : 2024-03-05 13:18:10 trace start 15secs #3
1:18:25 PM : 2024-03-05 13:18:25 trace end 15secs #3
1:18:38 PM : PrinectUpdateXJDF.exe Ended
: Process Completed.
When I uncommented the following line for showing the Logstring below
Logstring = "Pausing 15 seconds for Prinect processing" _
+ EndOfLine + "—————————————————————————————————————————————————————————————————————————————————————"
Me.AddUserInterfaceUpdate("Transaction":Logstring)
Even though the 100ms sleep was commented out the sleep time reduced to totally inconsistent periods. Weird.
1:07:38 PM : PrinectUpdateXJDF.exe Launched
1:08:41 PM : 2024-03-05 13:08:41 trace start 15secs #1
1:08:56 PM : 2024-03-05 13:08:56 trace end 15secs #1
1:08:59 PM : 2024-03-05 13:08:59 trace start 15secs #2
1:09:14 PM : 2024-03-05 13:09:14 trace end 15secs #2
1:09:17 PM : 2024-03-05 13:09:17 trace start 15secs #3
1:09:32 PM : 2024-03-05 13:09:32 trace end 15secs #3
1:09:35 PM : 2024-03-05 13:09:35 trace start 15secs #4
1:09:41 PM : 2024-03-05 13:09:41 trace start 15secs #5
1:09:50 PM : 2024-03-05 13:09:50 trace end 15secs #5
1:09:53 PM : 2024-03-05 13:09:53 trace start 15secs #6
1:09:56 PM : 2024-03-05 13:09:56 trace end 15secs #6
1:09:59 PM : 2024-03-05 13:09:59 trace start 15secs #7
1:10:08 PM : 2024-03-05 13:10:08 trace end 15secs #7
1:10:10 PM : 2024-03-05 13:10:10 trace start 15secs #8
1:10:14 PM : 2024-03-05 13:10:14 trace end 15secs #8
1:10:17 PM : 2024-03-05 13:10:17 trace start 15secs #9
1:10:25 PM : 2024-03-05 13:10:25 trace end 15secs #9
1:10:28 PM : 2024-03-05 13:10:28 trace start 15secs #10
1:10:32 PM : 2024-03-05 13:10:32 trace end 15secs #10
1:10:34 PM : PrinectUpdateXJDF.exe Ended
: Process Completed.
What was the purpose of teh 100msec sleep?
Are you on WIndows? Somewhere in the docs I read that sleep periods under Windows are unreliable BICBW.
Yes Windows. It appears it is the act of using UserInterfaceUpdate just before a sleep that is causing the inconsistency in sleep time. Not using it I get the full sleep. Still puzzling out how to log what I need and still get the full 15 seconds.
the 100ms sleep was to insure the logging happened without delay yielding some time to the UI.
Try logging with Print(), this goes to a log that you can view in Lifeboat or stdout when running by other means. This includes the benefit of not being tied to a Session.
I log to a file, so it doesn’t need to go via UserInterfaceUpdate. But the main thing is to actually have a logging mechanism. Something I learnt in the 1970s.
I log Transactions and Exceptions to separate log files but display what I’m logging in the UI as it’s happening so that the folks monitoring the application can validate that the app is processing, paused, etc.
The disturbing thing is your trace start and trace end are not in sequence, ie., you have two trace start back to back before another trace end. Is something kicking off another instance of the thread?
It isn’t supposed launch another thread, but as wonky as it is performing I’ve decided to re-engineer the entire process flow.
What the app does is:
every 60 seconds it checks a hot folder for files.
If one or more files exists it validates a job type against each file name using regular expressions.
the app then select the first file in the validated list of files to be the one to process.
The file is a text file with one job number per line.
The thread processes the job numbers serially to request current job specs via GET
the app reads the XML returned and then formats the specs into a specific XML called XJDF and sends the XJDF file path to a prepress server using XJMF.
The rest of the flow is rinse and repeat until no jobs left to process. This is the point that the thread re-enable the hot folder timer, the thread ends and the process will repeat until there are no files left or wait until new files arrive.
I’m considering re-engineering the workflow to serially launch a thread for each job that will run to completion before launching the next thread.
It would look differently if you added the times to a dictionary sent with AddUserInterfaceUpdate and output that property too. A UserInterfaceUpdate does not fire directly after an Add…, that’s why the GUI event has an array of dictionaries although you always send one. There might be an unpredictable delay between adding and updating.
This only happened when I uncommented the line for the UI update. I’m now convinced the UserInterfaceUpdate does strange things to the thread execution order. I may have to go back to an older way of logging from a thread.
There definitely is wonky unpredictability going on in this app that I haven’t encountered before in other places I’ve used it. I’m going to eliminate using it in favor of another method. I plan to have an array to stick the log lines in and a timer will just periodically read and clear the log lines and update the UI outside of the thread.
A
1:09:35 PM : 2024-03-05 13:09:3? trace end 15secs #4
is missing for some reason.
Maybe you have a thread.resume somewhere that’s forcing a resume?
We don’t see the UserInterfaceUpdate event handler. Could it be that only the first dictionary of the returned array is being checked?
I wouldn’t be impressed if Xojo ignored some events if the system were too busy when Xojo expected to fire it.
If he used System.DebugLog, I remember observing something like that using System.DebugLog, I guess it uses timers and not queues, and I guess some timer events are discarded when missing the mark.
Maybe using his own immediate log to file methods the missing lines show up.
I did not test if Xojo fixed that, but some versions ago you could lose final Updates when the thread finishes before the last UserInterfaceUpdate fires. That’s why I am using a custom thread subclass that keeps the thread alive until there are no more updates. But I never have seen missing parts in between when I iterate through the result array.
Yes. I don’t know if this is still the case. However, all my threads sleep fpr one second as the last thing they do, just in case.
@Tom_Dixon - this is in the code that allows you to update the UI correct?
When you said that you have a 100ms sleep here, what method are you calling… Thread.Sleep or App.DoEvents?