Get the most out of Planning Analytics’ logging capabilities
The ability to get detailed logs across various components of Planning Analytics is a crucial component in not only troubleshooting but ensuring optimal performance of your models.
Planning Analytics leverages the Log4j, a powerful and flexible logging library, which offers an effective way to capture, manage, and analyze various events and messages within the Planning Analytics environment. By utilizing Log4j, administrators and developers can gain valuable insights into the performance, behaviour, and troubleshooting of Planning Analytics applications.
This logging framework allows for the systematic recording of events, errors, and warnings, offering a transparent view into the inner workings of Planning Analytics, which is invaluable for monitoring, diagnostics, and optimization. In this context, understanding the principles and practices of Log4j logging in Planning Analytics can greatly enhance the ability to maintain and fine-tune your models.
Levels
Log4j can be configured to log messages using a log level or threshold which gives more or less verbose output or output only when certain conditions are met. Below are the options starting from least and working towards most verbose:
OFF -> FATAL -> ERROR -> WARN – > INFO -> DEBUG -> ALL
The more verbose you set the level to, the faster the logs files grow. Some files can reach 100MB in a few seconds based on the operations being performed and the logger being applied.
Default file
The Planning Analytics default file is called TM1s-log.properties
This file may already exist otherwise should be created in the same folder as your TM1s.cfg file.
The typical default file would look like the one below:
#
# Enable INFO level logging through the shared memory appender, by default. The server # will write informational messages, as well as errors and warnings to the log file.
#
log4j.logger.TM1=INFO, S1
# S1 is set to be a SharedMemoryAppender
log4j.appender.S1=org.apache.log4j.SharedMemoryAppender
# Specify the size of the shared memory segment
log4j.appender.S1.MemorySize=5 MB
# Specify the max filesize
log4j.appender.S1.MaxFileSize=100 MB
# Specify the max backup index
log4j.appender.S1.MaxBackupIndex=20
# Specify GMT or Local timezone
log4j.appender.S1.TimeZone=Local
The logger is specified as TM1 and relates to the options for the tm1server.log. The log level is set to INFO so should log any FATAL, ERROR, WARN and INFO messages for us but will not be as verbose to give us debug level detail.
The MaxFileSize controls the growth of each log. Our log will grow to around 100MB before it is cycled and becomes tm1server.log1
With the MaxBackupIndex set to 20, we would expect the tm1server.log to be cycled to a maximum of 20 files i.e. around 2GB of disk space consumed.
With that brief introduction, the next thing to look at is some of the frequently used loggers and how they can assist you.
Additional resources:
https://www.ibm.com/docs/sr/cognos-tm1/10.2.2?topic=log-logging-properties-file
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=file-enabling-disabling-logging
Frequently Used Loggers
TM1.Cube.Stargate, TM1.Cube.Stargate.ViewStorage, TM1.Cube.Stargate.Catalog
When trying to ascertain if your VMM and VMT settings have been adequately configured, you could use these loggers to assist in detailing how the stargates are built and destroyed, the memory consumed and elements involved in the view.
Sample Log4j configuration:
#--STARGATE
log4j.logger.TM1.Cube.Stargate=DEBUG, Stargate
log4j.logger.TM1.Cube.Stargate.ViewStorage=DEBUG, Stargate
log4j.logger.TM1.Cube.Stargate.Catalog=DEBUG, Stargate
log4j.additivity.TM1.Cube.Stargate=false
log4j.additivity.TM1.Cube.Stargate.ViewStorage=false
log4j.additivity.TM1.Cube.Stargate.Catalog=false
log4j.appender.Stargate=org.apache.log4j.SharedMemoryAppender
log4j.appender.Stargate.MemorySize=5 MB
log4j.appender.Stargate.File=TM1Stargate.log
log4j.appender.Stargate.MaxFileSize=50 MB
log4j.appender.Stargate.MaxBackupIndex=5
log4j.appender.Stargate.Timezone=Local
Note lines 4, 5 and 6 above, starting with log4j.additivity. This directive tells Log4j not to echo the logging to the tm1server.log as well. Doing so would grow your tm1server.log with duplicate information along with extra overhead of dual logging.
Sample log output:
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate.Definition
Cube: Scenario Configuration
Cube to View dimension map:
[0,1]
[1,0]
Stargate Expanse:
Dimension: Scenario
Axis Selections:
[ (Total Scenarios,U)
, …
]
Dimension: Scenario Configuration Measures
Title Element: Include in Default
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate dbstgCreate: Stargate::SlicerAggregator::Calculate (0x0000012D6ADFB010) in 0ms SGSize=24Kb workPoolSize=0Kb hPoolSize=16Kb.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate.Definition Axes Consolidation Subsets:
Dimension: Scenario
_S-Active Scenarios
…
Total Scenarios
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate dbstgCreate: dbstgCalculateConsolidationLevel_UseTree (0x0000012D6ADFB010) in 0ms SGSize=24Kb workPoolSize=8Kb hPoolSize=16Kb.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate dbstgCreate: dbstgStoreConsolidationsBack_UseTree (0x0000012D6ADFB010) in 0ms SGSize=24Kb workPoolSize=8Kb hPoolSize=16Kb.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate dbstgCreate: CalculateAxesConsolidations Stargate (0x0000012D6ADFB010) in 0ms
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate.Catalog Adding stargate: 0x0000012D6ADFB010 to catalog: 0x0000012D5EAAE868 of cube: 0x0000012D61282010.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate.Catalog Adding stargate: 0x0000012D6ADFB010 to catalog: 0x0000012D5EAAE868 of cube: 0x0000012D61282010.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate New Stargate Created (0x0000012D6ADFB010) in 0ms SGSize=24Kb workPoolSize=0Kb hPoolSize=16Kb.
40928 [2] DEBUG 2023-08-09 16:28:21.773 TM1.Cube.Stargate Destroying Stargate 0x0000012D6ADFB010
Additional resources:
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=management-about-stargate-views
Deep dive into TM1 Stargate views
TM1.Login
This logger is extremely useful in tracking attempted and successful logins into Planning Analytics. Many of us use the resultant log file as a data source for a TI to track last login dates for users. This is typically a compliance requirement to ensure that users who have not logged in for a set number of days are removed or requested to recertify their login.
Sample Log4j configuration:
#--LOGINS
log4j.logger.TM1.Login=DEBUG, LOGIN
log4j.additivity.TM1.Login=false
log4j.appender.LOGIN=org.apache.log4j.SharedMemoryAppender
log4j.appender.LOGIN.MemorySize=5 MB
log4j.appender.LOGIN.File=TM1Login.log
log4j.appender.LOGIN.MaxFileSize=5 MB
log4j.appender.LOGIN.MaxBackupIndex=5
log4j.appender.LOGIN.Timezone=Local
Sample log output:
40928 [2] DEBUG 2023-08-09 16:20:35.768 TM1.Login Login attempt by client: admin
40928 [2] DEBUG 2023-08-09 16:20:35.783 TM1.Login Login Success: User Admin
TM1.Event
The tm1server.log contains startup and shutdown information but this may be lost in the lines of detail and over time as the logs are cycled. You can log events like these to a separate file where you can review them more concisely. The TM1.Event file will also track issues where one process is blocking another from completing.
Sample Log4j configuration:
#--EVENT
log4j.logger.TM1.Event=DEBUG, Event
log4j.additivity.TM1.Event=false
log4j.appender.Event=org.apache.log4j.SharedMemoryAppender
log4j.appender.Event.MemorySize=5 MB
log4j.appender.Event.File=TM1Event.log
log4j.appender.Event.MaxFileSize=50 MB
log4j.appender.Event.MaxBackupIndex=5
log4j.appender.Event.Timezone=Local
Sample log output:
2023-08-03 08:37:05.427 INFO Server shutdown, elapsed time 2.00 seconds
2023-08-09 14:18:39.037 INFO TM1 Server is ready, elapsed time 6.00 seconds
2023-10-29 09:01:37.564 WARN Thread[1068] is blocking 5 other threads, and is in state [Run].
2023-10-29 09:01:37.564 WARN Thread[13076] is blocking 6 other threads, and is in state [Run].
2023-10-29 09:01:37.564 WARN Thread[25596] is blocking 5 other threads, and is in state [Run].
2023-10-29 09:01:37.564 WARN Thread[33576] is blocking 6 other threads, and is in state [Run].
2023-10-29 09:01:39.581 WARN Thread[37776] is blocking 5 other threads, and is in state [Run].
2023-10-29 09:01:42.604 WARN Thread[8692] is blocking 5 other threads, and is in state [Run].
2023-10-29 09:01:57.742 WARN Thread[27288] has been waiting in state [IXC] for 20(s), currently being blocked by Thread[13260].
Additional resources:
TM1.HttpRequest, TM1.HttpRequestBody, TM1.HttpResponse, TM1.HttpResponseBody
Applications like Planning Analytics Workspace and Planning Analytics for Excel make use of the REST API to communicate with the TM1 Engine (server). During troubleshooting times it is useful to be able to see what calls are being made. These loggers will give insights into the calls and responses.
Sample Log4j configuration:
#--REST API CALLS
log4j.logger.TM1.HttpRequest=DEBUG,HTTP
log4j.logger.TM1.HttpRequestBody=DEBUG,HTTP
log4j.logger.TM1.HttpResponse=DEBUG,HTTP
log4j.logger.TM1.HttpResponseBody=DEBUG,HTTP
log4j.additivity.TM1.HttpRequest=false
log4j.additivity.TM1.HttpRequestBody=false
log4j.additivity.TM1.HttpResponse=false
log4j.additivity.TM1.HttpResponseBody=false
log4j.appender.HTTP=org.apache.log4j.SharedMemoryAppender
log4j.appender.HTTP.File=TM1HTTP.log
log4j.appender.HTTP.MaxFileSize=20 MB
log4j.appender.HTTP.MaxBackupIndex=20
log4j.appender.HTTP.TimeZone=GMT
Sample log output:
6584 [1a] DEBUG 2023-10-21 13:46:08.993 TM1.HttpRequest GET /api/v1/Cellsets('J0XtU3APAIADAAAg')?$expand=Cube($select=Name,Attributes;$expand=Dimensions($expand=Hierarchies($select=Name,UniqueName,Attributes,Cardinality,Visible;$expand=Levels($select=Name,UniqueName,Cardinality,Number),ElementAttributes,PrivateSubsets($filter=tolower(replace(Name,'%20',''))%20eq%20'default';$select=Alias,Name,UniqueName,Expression,Hierarchy,Attributes,ExpandAbove);$orderby=tolower(Attributes/Caption)),DefaultHierarchy($select=UniqueName,Name)),MeasuresDimension($select=Name)),Axes($expand=Tuples($skip=0;$top=10;$expand=Members($select=Name,UniqueName,Attributes,Type,IsPlaceholder,Weight;$expand=Element($select=Type;$expand=Parents/$count),Parent($select=UniqueName))),Hierarchies($select=UniqueName)),Cells($skip=0;$top=70;$select=FormatString,Updateable,Consolidated,HasDrillthrough,FormattedValue,Status,RuleDerived,Ordinal,Value,Annotated,HasPicklist)
6584 [1a] DEBUG 2023-10-21 13:46:09.001 TM1.HttpResponse 200 OK
6584 [1a] DEBUG 2023-10-21 13:46:09.001 TM1.HttpResponseBody
Additional resources:
https://www.ibm.com/support/pages/planning-analytics-server-logging-odataplanning-analytics-workspace
TM1.Cube.Dependency
To track dependencies between cubes, you can write these to a separate log instead of sifting through the TM1Server.log.
Sample Log4j configuration:
#--Cube Dependencies
log4j.logger.TM1.Cube.Dependency=INFO, CubeDependency
log4j.additivity.TM1.Cube.Dependency=false
log4j.appender.CubeDependency=org.apache.log4j.SharedMemoryAppender
log4j.appender.CubeDependency.MemorySize=5 MB
log4j.appender.CubeDependency.File=TM1CubeDependency.log
log4j.appender.CubeDependency.MaxFileSize=50 MB
log4j.appender.CubeDependency.MaxBackupIndex=5
log4j.appender.CubeDependency.Timezone=Local
Sample log output:
29800 [] INFO 2023-10-21 16:27:35.028 TM1.Cube.Dependency Adding cube dependency: Cube 'Expense' depends on cube 'Exchange Rate'.
29800 [] INFO 2023-10-21 16:27:35.028 TM1.Cube.Dependency Adding cube dependency: Cube 'Expense' depends on cube '}ElementAttributes_Expense Measures'.
29800 [] INFO 2023-10-21 16:27:35.028 TM1.Cube.Dependency Adding cube dependency: Cube 'Expense' depends on cube '}ElementAttributes__S-General Ledger Account'.
29800 [] INFO 2023-10-21 16:27:35.028 TM1.Cube.Dependency Adding cube dependency: Cube 'Expense' depends on cube '}ElementAttributes_Cost Centre'.
29800 [] INFO 2023-10-21 16:27:35.029 TM1.Cube.Dependency Adding cube dependency: Cube 'Scenario Configuration' depends on cube '}ElementAttributes_Period'.
Additional resources:
https://www.ibm.com/docs/en/cognos-tm1/10.2.2?topic=dependencies-debugging-identifying-cube
TM1.Lock.Exception
Lock exceptions can arise for various reasons and may relate to process locking as well as file locking. In cases where antivirus has not been configured to exclude TM1 processes and/or file TM1 is unable to write back files to disk successfully as the antivirus creates a lock on those files.
You will notice that the log files will indicate that for example sales.cub$ could not be written. Typically TM1 creates the dollar file first when saving data to disk then deletes the old file and renames sales.cub$ to sales.cub. With another process having a lock on either file, this process cannot complete and could lead to changes not being saved correctly.
Similarly, locks could be in place when performing operations in TM1 e.g. running a process. Where other users are also running processes that need to deal with the same objection, this contention could lead to locking.
Sample Log4j configuration:
#--Lock Exception
log4j.logger.TM1.Lock.Exception=Debug, TM1LockException
log4j.additivity.TM1.Lock.Exception=false
log4j.appender.TM1LockException=org.apache.log4j.SharedMemoryAppender
log4j.appender.TM1LockException.MemorySize=5 MB
log4j.appender.TM1LockException.File=TM1LockException.log
log4j.appender.TM1LockException.MaxFileSize=50 MB
log4j.appender.TM1LockException.MaxBackupIndex=5
log4j.appender.TM1LockException.Timezone=Local
Sample log output:
9132 [] DEBUG 2023-09-24 12:09:23.018 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x0000005F086B7610) on object [View "OPEX Allocation-Export SKU Values_23276496435185", addr=0x0000006E682C7668, index=R-11270] in IX mode at C:\jks\prod\workspace\Build-tm1_main-tm1server-Win64-Production\src\tm1server\prod\tm1_r7s\TM1CubeImpl.cpp:17663 during function 'Unknown'. Entering wait state 'IXC'.
Blocked by the following 1 thread:
Thread 4176 holds the lock in IXNC mode
9132 [] DEBUG 2023-09-24 12:09:23.021 TM1.Lock.Exception Throwing IXNCConflict on object OPEX Allocation-Export SKU Values_23276496435185
9132 [] DEBUG 2023-09-24 12:09:23.021 TM1.Lock.Exception CommitActionLog::Rollback: Called for thread '9132' of user 'R*_S-Server-SaveDataAll' executing function 'Unknown'.
9132 [] DEBUG 2023-09-24 12:09:23.024 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x0000005F086B7610) on object [View "OPEX Allocation-Export SKU Values_23276496435185", addr=0x0000006E682C7668, index=R-11270] in IX mode at C:\jks\prod\workspace\Build-tm1_main-tm1server-Win64-Production\src\tm1server\prod\tm1_r7s\TM1CubeImpl.cpp:17663 during function 'Unknown'. Entering wait state 'IXC'.
Blocked by the following 1 thread:
Thread 4176 holds the lock in IXNC mode
8760 [32] DEBUG 2023-10-27 15:33:03.951 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x0000001DC3EE8010) on object [View "0000", addr=0x0000000C75B56368, index=P-53] in IX mode at C:\jks\prod\workspace\Build-tm1_main-tm1server-Win64-Production\src\tm1server\prod\tm1_r7s\TM1ViewImpl.cpp:3486 during request 'GET /api/v1/Cubes('OPEX Allocation')/PrivateViews'. Entering wait state 'IXC'.
Blocked by the following 1 thread:
Thread 11256 holds the lock in IX mode
8760 [32] DEBUG 2023-10-27 15:33:03.951 TM1.Lock.Exception Throwing IXNCConflict on object 0000
8760 [32] DEBUG 2023-10-27 15:33:03.965 TM1.Lock.Exception CommitActionLog::Rollback: Called for thread '8760' of user 'Admin' executing request 'GET /api/v1/Cubes('OPEX Allocation')/PrivateViews'.
8760 [32] DEBUG 2023-10-27 15:33:03.972 TM1.Lock.Exception Restarting request now.
Additional resources:
https://www.ibm.com/support/pages/how-troubleshoot-tm1-server-lock-contention
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=display-understanding-tm1-lock-modes
http://cubeac.com/blog/tips-tm1top/
MDX Logging
You may want to track what is being sent to the TM1 Engine as MDX requests. These may be from PAW, PAfE or other REST API calls.
Viewing the various logs would not only give insight into the code these UI’s generate and send but any errors in MDX used in requests would be highlighted e.g. bad set expressions, bad MDX to drvie dynamic reports.
TM1.MDXStatement
This logger allows you to see what MDX is being sent across views, sets etc.
Sample Log4j configuration:
#--MDX Statement
log4j.logger.TM1.MdxStatement=DEBUG, MDXStatement
log4j.additivity.TM1.MdxStatement=false
log4j.appender.MDXStatement=org.apache.log4j.SharedMemoryAppender
log4j.appender.MDXStatement.File=MDXStatement.log
log4j.appender.MDXStatement.MaxFileSize=20 MB
log4j.appender.MDXStatement.MaxBackupIndex=5
log4j.appender.MDXStatement.TimeZone=GMT
Sample log output:
11752 [1] DEBUG 2023-10-21 15:06:16.724 TM1.MdxStatement SELECT {} ON 0, {TM1SubsetToSet([Month].[Month],"MY","public")} ON 1 FROM [Revenue]
7408 [1] DEBUG 2023-10-21 15:06:22.294 TM1.MdxStatement SELECT {TM1SubsetToSet([product].[product],"Phones","public")} ON 0, {TM1SubsetToSet([Revenue].[Revenue],"Report","public")} ON 1 FROM [Revenue]
WHERE ([organization].[organization].[Total Company], [Month].[Month].[Q1^Jan], [Channel].[Channel].[Channel Total], [Year].[Year].[Y2], [Version].[Version].[Version 1])
Additional resources:
https://www.ibm.com/support/pages/how-enable-mdx-debug-logging-tm1-server
TM1.MDX.Interface
Only relevant in PA 2.0.6 and earlier to report on syntax issues.
Sample Log4j configuration:
#--MDX Interface
log4j.logger.TM1.MDX.Interface=DEBUG, MDXInterface
log4j.additivity.TM1.MDX.Interface=false
log4j.appender.MDXInterface=org.apache.log4j.SharedMemoryAppender
log4j.appender.MDXInterface.File=MDXInterface.log
log4j.appender.MDXInterface.MaxFileSize=20 MB
log4j.appender.MDXInterface.MaxBackupIndex=5
log4j.appender.MDXInterface.TimeZone=GMT
Sample log output:
11276 [6b5] ERROR 2017-10-16 13:51:10.237 TM1.Mdx.Interface
Syntax error at or near: 'hildren},{[Entity].[]})}', character position 21
Additional resources:
https://www.ibm.com/docs/el/planning-analytics/2.0.0?topic=logs-tm1mdxinterface-logger
TM1.Parallel
Adding TM1.Parallel will give detailed logging on processes run concurrently, split into work units etc. Think of what happens when MTQ is enabled and queries become multi-threaded or other operations like rules and feeders that may be executed in parallel.
Sample Log4j configuration:
#--Parallel Processing
log4j.logger.TM1.Parallel=DEBUG,Parallel
log4j.additivity.TM1.Parallel =false
log4j.appender.Parallel =org.apache.log4j.SharedMemoryAppender
log4j.appender.Parallel.File=TM1Parallel.log
log4j.appender.Parallel.MaxFileSize=100 MB
log4j.appender.Parallel.MaxBackupIndex=5
log4j.appender.Parallel.TimeZone=Local
To capture Stargate creation times add:
log4j.logger.TM1.Cube.Stargate=DEBUG
log4j.additivity.TM1.Cube.Stargate=false
To capture the event of operation threads picking work units:
log4j.logger.TM1.OperationThread=DEBUG
log4j.additivity.TM1.OperationThread=false
Additional resources:
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=configuration-multi-threaded-queries
Together with TM1.Cube.Stargate and TM1.OperationThread
TM1.Process
In cases where you may be running many hundreds or thousands of process like in a break-back or allocation that uses RunProcess, you can end up with very large and cluttered TM1Server logs. As of PA 2.0.8 rollback and restart messages are also written to the process log which could also create clutter with the writing of rollback and restart when using RunProcess.
You may choose to move the TI process related logs to their own file and keep the TM1Server log clean.
Sample Log4j configuration:
#--TM1 Process Statement
log4j.logger.TM1.Process=INFO, TM1Process
log4j.additivity.TM1.Process=false
log4j.appender.TM1Process=org.apache.log4j.SharedMemoryAppender
log4j.appender.TM1Process.File=TM1Process.log
log4j.appender.TM1Process.MaxFileSize=100 MB
log4j.appender.TM1Process.MaxBackupIndex=5
log4j.appender.TM1Process.TimeZone=Local
Sample log output:
8636 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population" run from process " Allocation-SKU-Store-Final Allocation Parallel Processing" by user "Admin"
11728 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population" run from process " Allocation-SKU-Store-Final Allocation Parallel Processing" by user "Admin"
11388 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population": finished executing normally, elapsed time 0.00 seconds
11388 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population" run from process " Allocation-SKU-Store-Final Allocation Parallel Processing" by user "Admin"
10372 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population": finished executing normally, elapsed time 0.00 seconds
10372 [19] INFO 2023-10-25 09:21:11.880 TM1.Process Process " Allocation-SKU-Store-Final Allocation Population" run from process " Allocation-SKU-Store-Final Allocation Parallel Processing" by user "Admin"
Additional resources:
TM1.SaveDataAll
In certain cases you may want to track what happens when you are calling a Save Data. This could happen via a TI process or when stopping the service.
The log will show you the sequence of events as well as the time take for each activity to complete.
Any issues e.g. locked files may be highlighted here otherwise check in the logs created by the TM1.Lock.Exception logger.
Sample Log4j configuration:
#--SaveDataAll
log4j.logger.TM1.SaveDataAll=DEBUG, SaveDataAll
log4j.additivity.TM1.SaveDataAll=false
log4j.appender.SaveDataAll=org.apache.log4j.SharedMemoryAppender
log4j.appender.SaveDataAll.File=TM1SaveDataAll.log
log4j.appender.SaveDataAll.MaxFileSize=20 MB
log4j.appender.SaveDataAll.MaxBackupIndex=5
log4j.appender.SaveDataAll.TimeZone=GMT
Sample log output:
40928 [2] DEBUG 2023-08-09 16:21:13.025 TM1.SaveDataAll Starting SaveDataAll
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Entering commit
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Acquiring cube creation lock
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Entering SaveDataAll critical section
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Write locking transaction log
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Current cube file dirtying event count (6) and Serialization count (0)
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Current feeder file dirtying event count (0) and Serialization count (0)
…
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll READONLY locking cube view map for cube 'Balance Sheet'
40928 [2] DEBUG 2023-08-09 16:21:13.027 TM1.SaveDataAll Releasing lock on cube view map for cube 'Balance Sheet'
…
40928 [2] DEBUG 2023-08-09 16:21:13.031 TM1.SaveDataAll Serializing cube 'Scenario Configuration'
40928 [2] DEBUG 2023-08-09 16:21:13.034 TM1.SaveDataAll Serializing cube '}CubeProperties'
40928 [2] DEBUG 2023-08-09 16:21:13.035 TM1.SaveDataAll Serializing cube '}DimensionProperties'
40928 [2] DEBUG 2023-08-09 16:21:13.036 TM1.SaveDataAll Serializing cube '}ElementAttributes_}Cultures'
40928 [2] DEBUG 2023-08-09 16:21:13.038 TM1.SaveDataAll Saving sets
40928 [2] DEBUG 2023-08-09 16:21:13.038 TM1.SaveDataAll Saving subsets
40928 [2] DEBUG 2023-08-09 16:21:13.041 TM1.SaveDataAll Saving calculated members
40928 [2] DEBUG 2023-08-09 16:21:13.041 TM1.SaveDataAll Saving processes
40928 [2] DEBUG 2023-08-09 16:21:13.042 TM1.SaveDataAll Saving chores
40928 [2] DEBUG 2023-08-09 16:21:13.042 TM1.SaveDataAll Entering commit
40928 [2] DEBUG 2023-08-09 16:21:13.050 TM1.SaveDataAll Reacquiring locks
40928 [2] DEBUG 2023-08-09 16:21:13.050 TM1.SaveDataAll Leaving SaveDataAll critical section
Additional resources:
https://www.ibm.com/support/pages/savedataall-best-practices
TM1.SSPI, TM1.SSPISecurity
When configuring Integrated Login it may be useful to enable these loggers to get an understanding of the user’s context. Sometimes there are issues between how the SPN has been configured and the users attempting to connect. TM1Web/PASS can get quite complicated when configuring the various files and something as trivial as case could trip you up. This logging may give you insights allowing you to correctly configure the settings.
Sample Log4j configuration:
#--SSPI
log4j.logger.TM1.SSPI=DEBUG, SSPI
log4j.logger.TM1.SSPISecurity=DEBUG, SSPI
log4j.additivity.TM1.SSPI=false
log4j.additivity.TM1.SSPISecurity=false
log4j.appender.SSPI=org.apache.log4j.SharedMemoryAppender
log4j.appender.SSPI.MemorySize=5 MB
log4j.appender.SSPI.File=TM1SSPI.log
log4j.appender.SSPI.MaxFileSize=50 MB
log4j.appender.SSPI.MaxBackupIndex=5
log4j.appender.SSPI.Timezone=Local
Sample log output:
9720 [20a] DEBUG 2023-02-23 11:21:46.493 TM1.SSPISecurity Server using Kerberos security package
9720 [20a] DEBUG 2023-02-23 11:21:46.493 TM1.SSPISecurity Package used is: Kerberos
9720 [20a] DEBUG 2023-02-23 11:21:46.493 TM1.SSPISecurity You are: ABC, from the XYZ domain
Additional resources:
TM1.SQL, TM1.SQLAPI
Sample Log4j configuration:
#--SQL
log4j.logger.TM1.SQL=DEBUG, SQL
log4j.logger.TM1.SQLAPI=DEBUG, SQL
log4j.additivity.TM1.SQL=false
log4j.additivity.TM1.SQLAPI=false
log4j.appender.SQL=org.apache.log4j.SharedMemoryAppender
log4j.appender.SQL.MemorySize=5 MB
log4j.appender.SQL.File=TM1SQL.log
log4j.appender.SQL.MaxFileSize=50 MB
log4j.appender.SQL.MaxBackupIndex=5
log4j.appender.SQL.Timezone=Local
Sample log output:
TM1.SQL
16992 [] DEBUG 2023-08-09 10:30:06.249 TM1.Sql CSqlQuery::Open( dsname = "XXX" , dsusername = "", sqlquery = "SELECT ... FROM XXX..Table with (NOLOCK) WHERE ... " )
16992 [] DEBUG 2023-08-09 10:30:09.103 TM1.Sql CSqlQuery::Close( dsname = "XXX" )
TM1.SQLAPI
3896 [] ERROR 2023-07-29 10:18:00.638 TM1.SQLAPI 23000[Microsoft][ODBC SQL Server Driver][SQL Server]Cannot insert duplicate key row in object 'dbo.DATxyz' with unique index 'XPKDATxyz'. The duplicate key value is (2023-07-28, 67477207-3593223, Column).
Additional resources:
https://www.ibm.com/support/pages/excessive-logging-when-using-usesqlfetch-t
TM1.TILogOutput
This is my “go to” log for writing details of the TI’s parameter and values, information from the TI e.g. no. records processed and is used extensively to log errors with sufficient context.
Without specifying the TM1.TILogOutput to direct any output to a separate file, all messages will be logged to the TM1Server.log which can add noise and clutter.
In a TI process you can write a function like the following to perform the LogOutput
LogOutput(“<Level>”,”<message>”); e.g.
LogOutput(‘ERROR’, ‘Semaphore file exists. Could not find an available thread. ‘ | sSemaphore);
Sample Log4j configuration:
log4j.logger.TM1.TILogOutput=INFO, LOGOUTPUT
log4j.additivity.TM1.TILogOutput=false
log4j.appender.LOGOUTPUT=org.apache.log4j.SharedMemoryAppender
log4j.appender.LOGOUTPUT.MemorySize=5 MB
log4j.appender.LOGOUTPUT.File=TM1LogOutput.log
log4j.appender.LOGOUTPUT.MaxFileSize=50 MB
log4j.appender.LOGOUTPUT.MaxBackupIndex=5
log4j.appender.LOGOUTPUT.Timezone=Local
Sample log output:
31024 [] INFO 2023-12-02 00:15:01.300 TM1.TILogOutput MD-_S-Customer-Import Customers-Caller: No files found to process!
31024 [] ERROR 2023-12-02 00:15:01.300 TM1.TILogOutput |MD-_S-Customer-Import Customers-Caller|R*MD-_S-Customer-Import Customers-Caller: No files found to process!
...
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Starting View: Balance Sheet - _S-D-Balance Sheet-Carry Forward Closing Balances_23346024351851
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Scenario Element=Actual
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Period Element=2023-NOV
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Balance Sheet Source Element=Total Balance Sheet Sources
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Company Code Subset=_S-All N
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Profit Centre Subset=_S-All N
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Intercompany Subset=_S-All N
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Balance Sheet Account Subset=_S-All N
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Transaction Currency Subset=_S-All N
10124 [] INFO 2023-12-02 00:35:04.591 TM1.TILogOutput Assigned: Reporting Currency Subset=_S-All N
...
28728 [] INFO 2023-12-02 04:01:26.526 TM1.TILogOutput MDX: EXCEPT(TM1DRILLDOWNMEMBER(UNION({[Profit Centre].[Total Profit Centres]},{[Profit Centre].[PC]}),ALL,RECURSIVE),TM1FILTERBYLEVEL(TM1DRILLDOWNMEMBER(UNION({[Profit Centre].[Total Profit Centres]},{[Profit Centre].[PC]}),ALL,RECURSIVE),0))
Additional resources:
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=functions-logoutput
Multi-threaded loading of individual cubes
TM1.Server.Loading
Allows you to capture individual timing of TM1 Server loading stages: DeSerializeDimensions, DeSerializeAttributeCubes, DeSerializeRegularCubes, GenerateServerSecurity.
TM1.Cube.Loading
Captures cube loading time, separately for .cub and .feeder files.
Sample Log4j configuration:
#--Server and Cube loading
log4j.logger.TM1.Server.Loading=DEBUG, LOADING
log4j.logger.TM1.Cube.Loading=DEBUG, LOADING
log4j.additivity.TM1.Server.Loading=false
log4j.additivity.TM1.Cube.Loading=false
log4j.appender.LOADING=org.apache.log4j.SharedMemoryAppender
log4j.appender.LOADING.MemorySize=5 MB
log4j.appender.LOADING.File=TM1Loading.log
log4j.appender.LOADING.MaxFileSize=50 MB
log4j.appender.LOADING.MaxBackupIndex=5
log4j.appender.LOADING.Timezone=Local
Sample log output:
9260 [] DEBUG 2023-12-02 12:37:47.132 TM1.Server.Loading ServerLoad: DeSerialized Attribute Cubes in 525ms.
9260 [] DEBUG 2023-12-02 12:37:47.763 TM1.Server.Loading ServerLoad: Updated Element Attributes in 1156ms.
9260 [] DEBUG 2023-12-02 12:37:47.850 TM1.Server.Loading ServerLoad: Updated Rule Aliases in 87ms.
9260 [] DEBUG 2023-12-02 12:37:48.035 TM1.Server.Loading ServerLoad: Loaded Rules in 154ms.
…
9260 [] DEBUG 2023-12-02 12:37:49.657 TM1.Cube.Loading TM1CubeImpl::LoadCubeBody: Done loading element maps in 0ms for cube 'Exchange Rate'.
9260 [] DEBUG 2023-12-02 12:37:49.659 TM1.Cube.Loading TM1CubeLoadWorkUnit::Run: Done bookmarking of cell data in 2ms for cube 'Exchange Rate'.
9260 [] DEBUG 2023-12-02 12:37:49.661 TM1.Cube.Loading TM1CubeImpl::LoadCubeBody: Done loading cell data in 5ms for cube 'Exchange Rate'.
9260 [] DEBUG 2023-12-02 12:37:49.664 TM1.Cube.Loading TM1CubeImpl::LoadCubeBody: Done loading element maps in 3ms for cube 'Expense'.
9260 [] DEBUG 2023-12-02 12:37:49.812 TM1.Cube.Loading TM1CubeLoadWorkUnit::Run: Done bookmarking of cell data in 147ms for cube 'Expense'.
9260 [] DEBUG 2023-12-02 12:37:50.044 TM1.Cube.Loading TM1CubeImpl::LoadCubeBody: Done loading cell data in 379ms for cube 'Expense'.
Additional resources:
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=pa2j22-tm1-server-updates
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=pitf-mtcubeload
TM1Web/PASS Logging
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=web-using-tm1-logging
log4j.logger.com.ibm.cognos.tm1.web.services.TM1Service=INFO
log4j.logger.com.ibm.cognos.tm1.web.services.TM1ExportService=DEBUG
log4j.logger.com.ibm.cognos.tm1.publish.Workbook=DEBUG
log4j.logger.com.ibm.cognos.tm1.web.services.TM1ServerSessionInfo=DEBUG
Admin Server Logging
https://www.ibm.com/docs/en/cognos-tm1/10.2.2?topic=log-configuring-admin-server-logging
TOP Logger
Sample Log4j configuration:
#--TOP
log4j.logger.Top=DEBUG, Top
log4j.additivity.Top=false
log4j.appender.Top=org.apache.log4j.SharedMemoryAppender
log4j.appender.Top.MemorySize=5 MB
log4j.appender.Top.File=TM1Top.log
log4j.appender.Top.MaxFileSize=50 MB
log4j.appender.Top.MaxBackupIndex=5
log4j.appender.Top.Timezone=Local
Sample log output:
2420 [] INFO 2023-10-21 16:05:57.286 Top.Title 24retail
2420 [] INFO 2023-10-21 16:05:57.286 Top 6968 Th:Pseudo - Idle - - - - 0
2420 [] INFO 2023-10-21 16:05:57.286 Top 3956 Th:DynamicConfig - Idle - - - - 0
2420 [] INFO 2023-10-21 16:05:57.286 Top 7572 Admin Workspace:26 Idle - - - - 0
2420 [] INFO 2023-10-21 16:05:57.286 Top 10132 Admin Workspace:26 Idle - - - - 0
2420 [] INFO 2023-10-21 16:05:57.286 Top
2420 [] INFO 2023-10-21 16:06:02.302 Top.Title 24retail
2420 [] INFO 2023-10-21 16:06:02.302 Top 6968 Th:Pseudo - Idle - - - - 0
2420 [] INFO 2023-10-21 16:06:02.302 Top 3956 Th:DynamicConfig - Idle - - - - 0
2420 [] INFO 2023-10-21 16:06:02.302 Top 7572 Admin Workspace:26 Idle - - - - 0
2420 [] INFO 2023-10-21 16:06:02.302 Top 10132 Admin Workspace:26 Idle - - - - 0
2420 [] INFO 2023-10-21 16:06:02.302 Top 3932 Admin Workspace:26 Run:R - POST /api/v1/Processes('RefreshMdxHierarchy')/tm1.ExecuteWithReturn - 3
2420 [] INFO 2023-10-21 16:06:02.302 Top 3080 Admin Workspace:26 Idle - - - - 0
2420 [] INFO 2023-10-21 16:06:02.302 Top
Additional resources:
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=logs-tm1-top-log
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=utility-running-tm1-top
Operations Logger
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=logs-ops-logger
Client Logger
https://www.ibm.com/docs/da/planning-analytics/2.0.0?topic=tools-client-logging
All Available Loggers
To generate a list of all available loggers, stop the server and add the following to the TM1s-log.properties file:
log4j.logger.TM1.MetaLogger=DEBUG
Start the server again and the available loggers will be written to the TM1Server.log
For my version PA 2.0.9.18 (TM1 Build Number: 11.8.02200.2) I get the list per below:
List of Loggers
- TM1.AdminServerRegLogger
- TM1.API
- TM1.API.Fn
- TM1.API.Parameters
- TM1.API.Retry
- TM1.API.Return
- TM1.API.Return.Error
- TM1.API.Return.Object
- TM1.API.Return.String
- TM1.API.Top
- TM1.APIDetail
- TM1.APIDetail.Parameters
- TM1.APIDetail.Parameters.ExpandArray
- TM1.APIDetail.Return
- TM1.APIDetail.Return.Array
- TM1.APIDetail.Return.Array.Cube
- TM1.APIDetail.Return.Array.Dimension
- TM1.APIDetail.Return.Array.Subset
- TM1.APIDetail.Return.Array.View
- TM1.APIDetail.Return.Bool
- TM1.APIDetail.Return.Index
- TM1.APIDetail.Return.Real
- TM1.Application
- TM1.Audit
- TM1.Audit.PostProcessor
- TM1.Audit.Query
- TM1.Audit.Reader
- TM1.Audit.ResultSet
- TM1.Base
- TM1.Base.GetImpl
- TM1.Blob
- TM1.CAMSecurity
- TM1.CAMSecurity.ClientCreation
- TM1.CAMSoap
- TM1.Catalog
- TM1.CheckLockHeld
- TM1.Chore
- TM1.Client
- TM1.Client.Detail
- TM1.ClientMessage
- TM1.Cognos
- TM1.ColIterator
- TM1.Comm
- TM1.Comm.SSL
- TM1.Comm.SSL.Cert
- TM1.Commit
- TM1.Commit.Data
- TM1.Connection
- TM1.Connection.RSData
- TM1.ConnectionRequestThread
- TM1.Context.Cancel
- TM1.CRYPT
- TM1.Csv
- TM1.Cube
- TM1.Cube.Batch
- TM1.Cube.CalculationCache
- TM1.Cube.CalculationCache.Cell
- TM1.Cube.Commit
- TM1.Cube.Dependency
- TM1.Cube.Drill
- TM1.Cube.Invalidation
- TM1.Cube.Invalidation.Precise
- TM1.Cube.Invalidation.PreciseThreshold
- TM1.Cube.Iterator
- TM1.Cube.Loading
- TM1.Cube.Partition
- TM1.Cube.Partition.Expanse
- TM1.Cube.Picklist
- TM1.Cube.RuleStats
- TM1.Cube.Save
- TM1.Cube.Spreading
- TM1.Cube.Stargate
- TM1.Cube.Stargate.Catalog
- TM1.Cube.Stargate.Definition
- TM1.Cube.Stargate.Reference
- TM1.Cube.Stargate.SkipStargate
- TM1.Cube.Stargate.ViewStorage
- TM1.Cube.Subscription
- TM1.Cube.ThreadCalculation
- TM1.Cube.VersionedTree
- TM1.Cube.VersionedTree.References
- TM1.Cube.VersionedTree.Versions
- TM1.Cubeload
- TM1.DataReservation
- TM1.DataSource
- TM1.DataSource.CubeView
- TM1.Dimension
- TM1.Dimension.Element
- TM1.Dimension.ElementPool
- TM1.Dimension.PseudoEle
- TM1.Element
- TM1.Event
- TM1.File
- TM1.Folder
- TM1.Git
- TM1.Git.Detail
- TM1.GlobalCollection
- TM1.GlobalObjectCache
- TM1.Group
- TM1.GSKit
- TM1.Hierarchy
- TM1.HierarchyLevel
- TM1.HttpRequest
- TM1.HttpRequestBody
- TM1.HttpRequestHeaders
- TM1.HttpResponse
- TM1.HttpResponseBody
- TM1.HttpResponseHeaders
- TM1.HttpSession
- TM1.LDAPAuth
- TM1.Lock
- TM1.Lock.CriticalSection
- TM1.Lock.Exception
- TM1.Lock.SYSMT
- TM1.Login
- TM1.LoginAPI
- TM1.LoginAPI.Parameters
- TM1.LoginAPI.Retry
- TM1.LoginAPI.Return
- TM1.LoginAPI.Return.Error
- TM1.LoginAPI.Return.Object
- TM1.LoginAPI.Return.String
- TM1.LoginAPIDetail
- TM1.LoginAPIDetail.Parameters
- TM1.LoginAPIDetail.Parameters.ExpandArray
- TM1.LoginAPIDetail.Return
- TM1.LoginAPIDetail.Return.Array
- TM1.LoginAPIDetail.Return.Bool
- TM1.LoginAPIDetail.Return.Index
- TM1.LoginAPIDetail.Return.Real
- TM1.Mdx
- TM1.Mdx.Interface
- TM1.MdxStatement
- TM1.MdxViewCreate
- TM1.MetaLogger
- TM1.NGAPI
- TM1.NGAPI.FACET
- TM1.NGAPI.REST
- TM1.Object
- TM1.ObjectIndex
- TM1.ObjectRegistry
- TM1.ODBC
- TM1.Odbo
- TM1.OdboRowset
- TM1.OdboSchema
- TM1.OdboSchema.MeasuresRowset
- TM1.OdboSchema.MembersRowset
- TM1.OID
- TM1.OID.Curl
- TM1.OID.JWK
- TM1.OID.JWT
- TM1.OldQuery
- TM1.OperationThread
- TM1.Parallel
- TM1.Parallel.Operation
- TM1.Parallel.SplitPlan
- TM1.Parallel.Splits
- TM1.Process
- TM1.Process.Functions
- TM1.Process.Functions.Parameters
- TM1.Process.Variables
- TM1.Query
- TM1.Registration
- TM1.Rowset
- TM1.Rule
- TM1.Rule.Analysis
- TM1.Rule.Analysis.Details
- TM1.Rule.Analysis.ParseTree
- TM1.Rule.Analysis.Subscription
- TM1.Rule.ElementAliases
- TM1.Rule.Evaluation
- TM1.Sandbox
- TM1.Sandbox.Invalidation.Precise
- TM1.Sandbox.Merge
- TM1.Sandbox.Merge.Parameters
- TM1.Sandbox.Merge.Queue.Request
- TM1.SandboxDimension
- TM1.Sap
- TM1.Sap.Detail
- TM1.SaveDataAll
- TM1.Security
- TM1.Server
- TM1.Server.Busy
- TM1.Server.Config
- TM1.Server.Config.Registry
- TM1.Server.Distributed
- TM1.Server.Loading
- TM1.Server.locale
- TM1.Server.Memory
- TM1.Server.Memory.Debug
- TM1.Server.Memory.MemBytes
- TM1.Server.Memory.PoolBytes
- TM1.Server.Memory.PoolCount
- TM1.Server.NB.Acceptor
- TM1.Server.NB.FunctionReader
- TM1.Server.NB.PacketReader
- TM1.Server.NB.Reactor
- TM1.Server.NB.ResponsePacker
- TM1.Server.NB.ThreadPool
- TM1.Server.NB.TM1SessionIOMonitor
- TM1.Server.NB.UserSession
- TM1.Server.Network
- TM1.Server.Network.APIPack
- TM1.Server.Network.APIUnpack
- TM1.Server.Network.Detail
- TM1.Server.Threads
- TM1.ServerGroupMap
- TM1.Set
- TM1.Sip
- TM1.Sql
- TM1.SQLAPI
- TM1.SSPI
- TM1.SSPISecurity
- TM1.StatsMonitor
- TM1.Subset
- TM1.System
- TM1.System.File
- TM1.TILogOutput
- TM1.TM1Top
- TM1.Transaction
- TM1.UI
- TM1.Updates
- TM1.View
- TM1.ViewArray
Further Resources
https://www.ibm.com/docs/en/planning-analytics/2.0.0?topic=logs-logging-properties-file
https://www.ibm.com/support/pages/write-tm1-server-debug-logging-alternate-file
https://www.ibm.com/docs/da/planning-analytics/2.0.0?topic=tools-client-logging
https://www.tutorialspoint.com/log4j/log4j_logging_levels.htm
Conclusion
There are certainly plenty of options available to track any number of events, warnings and errors.
In some cases the information generated can be overwhelming and even meaningless without the necessary tools and knowledge to decrypt the results. This however should not stop you from applying some of the loggers to your environment, and obviously in a development environment first to ascertain the impact of any logs enabled.
I look forward to any comments on the above and am keen for you to share your experiences here on where these have helped you and how, as well as sharing detail on loggers not covered above.
By George Tonkin, Business Partner at MCi.