TM1 Forum

Toda, we suffered for server hang. I try to make a savedata action before stop server, but fail, server said to savedata action can not get lock. So I had to kill the tm1d process, and restart sever.

When the server is restart as a service, I believe it recovers from log, but some clients reported their work several hours ago lost. And it looks wield. Some users recent work is OK, but some users hours ago work lost.

I tried to find some information in t1mserver.log, and find 2 lines of DEBUG message (at bottom of below) looks strange. not sure what happens in actual. Could someone help to have a look and give some clue?

many thanks.



1720 [46] INFO 2015-03-26 14:14:50.810 TM1.Dimension Dimension Current_OU_FY15 changed by user Admin
5828 [102] INFO 2015-03-26 14:15:40.434 TM1.Cube Loading body for cube Utilization_Input
5828 [102] INFO 2015-03-26 14:15:40.434 TM1.Cube Loading body for cube Promotion%_Highlevel_Planning
5828 [102] INFO 2015-03-26 14:15:40.434 TM1.Cube Loading body for cube SDC_Charges
5828 [102] INFO 2015-03-26 14:15:40.434 TM1.Cube Loading body for cube AR_Provisions%
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Turnover%
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Turnover_Input
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Staff_Based_Revenue
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Recovery_Rate%
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Utilization%
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Headcount
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Staff_Based_Revenue_Highlevel_Planning
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube SDC_Charge_Out_Rate
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Current_OU_FY15_Mapping
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Staff_Costs_Highlevel_Planning
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Charge_Out_Rate
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube HC_CY_Forecast
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Headcount_Highlevel_Planning
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Promotion%
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Client_Info
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube SDC_Supply_Hours
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube SDC_Demand_Hours
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube HC_CY_Forecast_Highlevel
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Standard_Hours
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Cube Loading body for cube Promotion_Highlevel_Planning_Input
5828 [102] INFO 2015-03-26 14:15:40.450 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Utilization_Input'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Utilization_Input'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Promotion%_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Promotion%_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'SDC_Charges'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'SDC_Charges'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Turnover%'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Turnover%'.
5828 [102] INFO 2015-03-26 14:15:40.465 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Turnover_Input'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Turnover_Input'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Staff_Based_Revenue'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Staff_Based_Revenue'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Recovery_Rate%'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Recovery_Rate%'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Utilization%'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Utilization%'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Headcount'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Headcount'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Staff_Based_Revenue_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Staff_Based_Revenue_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'SDC_Charge_Out_Rate'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'SDC_Charge_Out_Rate'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Current_OU_FY15_Mapping'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Current_OU_FY15_Mapping'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Staff_Costs_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Staff_Costs_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Charge_Out_Rate'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Charge_Out_Rate'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'HC_CY_Forecast'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'HC_CY_Forecast'.
5828 [102] INFO 2015-03-26 14:15:40.496 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Headcount_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Headcount_Highlevel_Planning'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Promotion%'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Promotion%'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'SDC_Supply_Hours'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'SDC_Supply_Hours'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'SDC_Demand_Hours'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'SDC_Demand_Hours'.
5828 [102] INFO 2015-03-26 14:15:40.512 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'HC_CY_Forecast_Highlevel'.
5828 [102] INFO 2015-03-26 14:15:40.543 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'HC_CY_Forecast_Highlevel'.
5828 [102] INFO 2015-03-26 14:15:40.543 TM1.Server TM1CubeImpl::ProcessFeeders: Computing feeders for delta cube 'Promotion_Highlevel_Planning_Input'.
5828 [102] INFO 2015-03-26 14:15:40.606 TM1.Server TM1CubeImpl::ProcessFeeders: Done computing feeders for delta cube 'Promotion_Highlevel_Planning_Input'.
2020 [10b] DEBUG 2015-03-26 14:25:11.316 TM1.Blob CommitDeferredFileCommand - BLOB_FILE_CLOSE is pending all blob readers to drain out. Any updates will not be fully committed until this happens or the server is shutdown.
2020 [10b] DEBUG 2015-03-26 14:25:11.316 TM1.Blob CommitDeferredFileCommand - BLOB_FILE_CLOSE is pending all blob readers to drain out. Any updates will not be fully committed until this happens or the server is shutdown.

Right before I force the server stop, there is 2 messages for save data can not be executed.

2024 [1d1] INFO 2015-03-26 16:34:47.513 TM1.Process Process "Server_Online_Backup" executed by user "Admin"
2024 [1d1] WARN 2015-03-26 16:34:47.529 TM1.Lock Attempt to release lock on 0x00000000075C2A58(0x00000000076FC9B8). No lock held.

6164 [] INFO 2015-03-26 16:46:55.097 TM1.Server Closing...
6164 [] INFO 2015-03-26 16:46:55.097 TM1.Server Saving...
6164 [] INFO 2015-03-26 16:46:55.097 TM1.Server The server is coming down...
6164 [] INFO 2015-03-26 16:46:55.097 TM1.Server TM1ServerImpl::Destroy: disconnect clients
5368 [ce] DEBUG 2015-03-26 16:46:55.128 TM1.Process ExecuteProcedures: Cancel request received.

I would hazard a guess that the log files are telling you the issue in fairly coherent terms (which admittedly is unusual for the logs); TM1 requires a permanent lock to the tm1s.log file but every so often something like a virus scanner will steal that lock causing TM1 to lose its marbles. Hence your original issues.

The lack of data could be due to that lock being stolen meaning that TM1 couldn't write the data out to the log file so it was unable to load it back in on startup and/or you don't have logging enabled for all your cubes in the first place.

It could be something else but the old virus scanner taking over your locks is a fairly common issue and it's good practice to ask your IT guys to put in a rule that ignores the logs folder as part of their scans etc.

In addition, What does below log say.

3532 [f4] DEBUG 2015-03-27 11:44:38.774 TM1.Blob CommitDeferredFileCommand - BLOB_FILE_CLOSE is pending all blob readers to drain out. Any updates will not be fully committed until this happens or the server is shutdown.


Does it hurt the system? I found similar logs frequently in tmserver.log file. What action causes this log?



Regards,
Chris

Blob-files ("TM1.Blob") are heavily used by TM1 for many things. For instance, to store the formatting information of a Rules file (*.RUX) or as pointers to some file in the Application Organizer. The file extension of a Blob-file is *.blb. Some file operations, (i.e. to create a new .blb file or to open, edit and close an existing .blb file), are expensive in terms of TM1 server performance. Thus these file operations are not executed on demand, but instead are deferred/delayed for some seconds/minutes (CommitDeferredFileCommand) until a time period the TM1 server is less busy and thus can "afford" to execute them.

This is a normal behavior.