Threads disappear without a trace from message log

[lotsaram]

I have a rather curious phenomenon where we have a model which loads a lot of data on a lot of threads with tm1runti. Sometimes a thread just "disappears", that is you see the thread appear in tm1top with function ProcessExecuteEx and a corresponding match in the tm1server.log that the thread logs in and calls a TI process, ... but when the thread disappears from tm1top there is not a corresponding process complete or logout line logged to the message log or any process error message in the log directory. It is as if the thread vanished without trace.

So why is this even an issue?
There is a very large volume of data to process in a very limited timeframe. (Many many many millions of records within a window of a few minutes). So an optimized process with tm1runti is critical which is triggered externally and managed end-to-end as there are several pre-processing steps before TM1 in the source system and DWH layers before the several steps within TM1. The scheduling tool is watching the tm1server.log (among other things) to coordinate end-to-end data flows and trigger the next step in the process when the preceding job finished. If a process which it is waiting to finish just "disappears" then the dataflow stalls and the next step is never triggered. When this happens manual intervention is needed to complete the data processing. The data flow needs to be completely automated. That in a nutshell is why this is an issue, and a critical one.

It seems to be random which processes/threads are affected but does seem to happen to some more often than others. My unfounded assumption would be it is a bug or deficiency in the tm1server.log that it only has granularity to millisecond level and if more than one thread wants to log a message in the same millisecond then it is first come first served with 2nd and subsequent log lines with the same millisecond ID just don't get logged? Has anyone else observed this? Can anyone else confirm this?

[BrianL]

I've never heard of any issues with log4cxx dropping log messages.

Are the threads completing their work successfully, and just not logging a completion message? Or is the work not getting done?

[qml]

I have never seen log entries not being recorded either.

However, in the case of a rollback you might see more Process "X" run messages in the log than Process "X": finished executing normally messages. But I don't suspect that has anything to do with your case and, if I understand right, your TIs also finish fine, despite the lack of log records.

Could it be that your scheduling tool is acquiring a lock on the log for a split second and preventing the TM1 server from writing messages to the log? Does this happen to any other message types? Does it happen when the scheduling tool is not monitoring the log?

[lotsaram]

I've never heard of any issues with log4cxx dropping log messages.

Are the threads completing their work successfully, and just not logging a completion message? Or is the work not getting done?

Right now the application is in acceptance testing. Our assumption is that the work is getting done but the completion isn't logged. But it is hard to be absolutely certain as there are several hundred, maybe even several thousand threads executing at between 30 - 60 simultaneously over a period of around 30 - 60 minutes. So if just one or 2 threads don't conclude the logging it is pretty hard to pin down.

[BrianL]

Since this isn't in Production and overhead isn't as big of a concern you could try enabling some logging.

[/code]log4j.logger.TM1.Server.Threads=DEBUG[/code]

or even

Code: Select all

log4j.logger.TM1.Process=DEBUG
log4j.logger.TM1.Process.Functions=INFO
log4j.logger.TM1.Process.Functions.Parameters=INFO
log4j.logger.TM1.Process.Variables=INFO

Lock.Exception logging would already tell you if the thread is hitting rollback. There's a TM1.Commit logger too, but that's really verbose.