Product: TIBCO Spotfire®
How to determine the data table load or refresh times in TIBCO Spotfire
If there are unexpectedly long delays seen when loading data tables in an analysis we may be interested in investigating the refresh/load times of each data table.
There are two ways to get this information:
1. Using Diagnostics dialog
This approach is only helpful if you are loading analysis files on the TIBCO Spotfire Analyst/Desktop client. After the analysis is loaded, you can go to Help > Support Diagnostics and Logging > Diagnostics
There you can see each data table refresh duration. Only operations/data tables which are linked to source would be visible in this section i.e. which were refreshed either from data source or from stored data. For Embedded data tables, total time taken for all data tables will be seen.
2. Log entries:
This approach is applicable for both TIBCO Spotfire Analyst/Desktop clients and the TIBCO Spotfire Web Player. To get complete details about data table loading, ensure the Web Player or Analyst clients are logging in debug mode where the issue is being replicated. Read more for enabling debug mode on Node Manager/Web Player and on Analyst/Desktop
Once debug mode is enabled, load the analysis file in the respective clients. Once the analysis is loaded, go to Spotfire.Dxp.Worker.Host.Debug log for Web Player and the Support.Dxp.Diagnostics log for the Spotfire Analyst/Desktop installed clients.
Total Data Table refresh time:
Search on "Setting refreshing on table" in logs. There would be many entries of setting refresh to True or False. "Setting refreshing on table Customer_IL to True." means refresh start has been triggered whereas "Setting refreshing on table Customer_IL to False." means data table refresh is complete. So listing these start and end refresh time for each data table, you would get the total time that data table took for refresh.
Information link/Data Connection refresh time:
Below log entries are applicable only for linked to source and imported data tables.
1. Information Link:
If you want to see how much time an Information link present in that data table took, you will need to search on "Type: Information Link". You will get some entries like below, where 19014 ms is the time taken for Information link refresh. The other number beside it is number of rows imported:
DEBUG;2020-05-22T15:55:24,522-07:00;2020-05-22T20:55:24,522;4c72cfcf-a4df-4b42-8d88-91116abc6023;2216154e96uKMs;108;abc;Spotfire.Dxp.Framework.Utilities.ServerLoggerManager;"Server log manager logged Audit: 2020-05-22T15:55:24,082-05:00, , datasource_pro, execute, True, , /InformationLinks/Customer_IL, Customer_IL, 1. Select Data > Add... Type: Information Link Path: /InformationLinks/Customer_IL Id: bbd487d8-a07d-4d95-8e3c-97f9455584d1 , 19014, 30403, , ."
You can even check the same in sql.log present on the TIBCO Spotfire Server (<TIBCO Installation Folder>/tomcat/logs). Search on information link guid:
2020-05-22T15:55:05,031-0700 [*pool-13-thread-1, abc, #48, #79834*]: Executing Information Link 'Customer_IL' (bbd487d8-a07d-4d95-8e3c-97f9455584d1)
2020-05-22T15:55:24,359-0700 [*pool-13-thread-2, abc, #48, #79834*]: Information Link 'Customer_IL' (bbd487d8-a07d-4d95-8e3c-97f9455584d1) executed successfully, time: 18.909 seconds
2020-05-22T15:55:24,546-0700 [*Thread-41, abc, #48, #79834*]: Information Link 'Customer_IL' (bbd487d8-a07d-4d95-8e3c-97f9455584d1) job closed, time: 19.014 seconds
Information link "executed" time is the time taken for execution on database whereas "job closed" time is the total time taken to complete the job of bringing results back in to the data table in the client.
2. Data Connection:
If you want to see how much time a data connection present in that data table took, you will need to search on "data_connector_pro" or "Connection type:". You will get some entries like below, where 1798 ms is the time taken for data connection refresh. The other number beside it is number of rows imported.
2020-05-22T16:25:18,059-04:00 2020-05-22 20:25:18,059 abc [39] DEBUG Spotfire.Dxp.Framework.Utilities.ServerLoggerManager [(null)] - Server log manager did not log Audit since category is disabled: 2020-05-22T16:25:18,057-04:00, , data_connector_pro, get_data, True, ec43da17-bcc2-43c4-bbb4-a1658f2b7ad2, /dataconnection/testsqlserver, Spotfire.SqlServerAdapter, Connection type: Microsoft SQL Server Server: abcd Database: testview Encrypt: True Authentication method: SQL Server authentication Trust server: True , SELECT "dbo#AllocPROD1555448887872"."WELL_NAME" AS "WELL_NAME", "dbo#AllocPROD1555448887872"."MUWI" AS "MUWI", "dbo#AllocPROD1555448887872"."PRODRATE" AS "PRODRATE", "dbo#AllocPROD1555448887872"."DECLINERATE" AS "DECLINERATE", "dbo#AllocPROD1555448887872"."DECLINETYPE" AS "DECLINETYPE", "dbo#AllocPROD1555448887872"."BFACTOR" AS "BFACTOR", "dbo#AllocPROD1555448887872"."STARTCUM" AS "STARTCUM", "dbo#AllocPROD1555448887872"."ENDRATE" AS "ENDRATE", "dbo#AllocPROD1555448887872"."PHASE" AS "PHASE", "dbo#AllocPROD1555448887872"."NOMINALRATE" AS "NOMINALRATE", "dbo#AllocPROD1555448887872"."ULTIMATE" AS "ULTIMATE", "dbo#AllocPROD1555448887872"."DeltaStart" AS "DeltaStart", "dbo#AllocPROD1555448887872"."DeltaEnd" AS "DeltaEnd", "dbo#AllocPROD1555448887872"."TotalMonths" AS "TotalMonths", "dbo#AllocPROD1555448887872"."MonthNo" AS "MonthNo", "dbo#AllocPROD1555448887872"."OilRate" AS "OilRate", "dbo#AllocPROD1555448887872"."AllocatedProduction" AS "AllocatedProduction" FROM "dbo#AllocPROD1555448887872" AS "dbo#AllocPROD1555448887872", 29192, 1798, , .
If you want to know the refresh time taken only for database refresh (excluding time taken to fetch records in Spotfire data table), search on "Executing query (". Ensure that it is the relevant query. The line above that will be similar to this example below which will contain query execution time on database:
DEBUG;2019-04-02T12:47:04,929-07:00;2019-04-02 19:47:04,929;4c72cfcf-a4df-4b42-8d88-91116abc6023;2216154e96uKMs;46;abc;Spotfire.Dxp.Data.Adapters.SqlServer.SqlServerAdapterConnection;"SqlServer query completed in 9642 ms. Retrieved 5 columns and 5037 rows."
3. On demand data table refresh time:
On demand data table can be created either through information link or data connection. If you search on "dataondemand", all entries related to this phrase will appear. In the case of an information link, below entries will be relevant. In the first log entry at the end, it shows 8.685 seconds which is the data on demand execution time. Note that for information links, the execution time can be obtained from sql.log file as explained above.
Information Link:
2020-02-26 12:49:15,728-04:00 2020-02-26 18:49:15,8385 abc [TF Spotfire.Dxp.Data.DataFunctions.DataFunctionImpl+DataFunctionWorkerFactory] DEBUG Spotfire.Dxp.Data.DataFunctions.DataFunctionImpl [(null)] "Execute Data Function;;DataOnDemand-82f072f8-eadb-4984-8c06-1b04467165fe;Success;USWTCTXNP018;2020-02-26T12:49:06,872-06:00;2020-02-26 18:49:06,872;2020-02-26 18:49:15,557;8.685;"
2020-02-26T12:49:15,728-04:00 2020-02-26T18:49:15,8386 abc [42] DEBUG Spotfire.Dxp.Data.DataFunctions.DataFunctionImpl [(null)] "Server log manager logged Audit: 2020-02-26T12:49:15,558-06:00, , datafunction_pro, execute, True, , DataOnDemand-82f072f8-eadb-4984-8c06-1b04467165fe, 1. Information Link Path: /abc/ondemandIL Id: 82f072f8-eadb-4984-8c06-1b04467165fe On-demand settings Column to filter by: Source Expression: [Summary].[test #] Limited by active filtering scheme: No Limited by: test Summary Update behavior: Automatic Caching allowed: No , 53453, , , ."
Data Connection:
When using data connection, below log entry shows data on demand execution time at end i.e. 3995 ms
2020-05-06T15:58:57,931-07:00 2020-05-06 22:58:57,931 abc [55] DEBUG Spotfire.Dxp.Framework.Utilities.ServerLoggerManager [(null)] - Server log manager logged Audit: 2020-05-06T15:58:57,931-07:00, , datafunction_pro, execute, True, , DataOnDemand-90bcde7d-1ea1-44d5-a8e1-4fd7c91ad6d0, 1. Imported data table from data connection. Connection name: Test Path to connection in library: /abc/TestOnDemand View name: Baseball Connection type: Amazon Redshift Server: xxxx.redshift.amazonaws.com:5439 SSL mode: disable Database: def On-demand settings Column to filter by: Runs Range (Min) Expression: "5" Limited by active filtering scheme: No Limited by: (None) Range (Max) Expression: "1000" Limited by active filtering scheme: No Limited by: (None) Update behavior: Automatic Caching allowed: Yes , 3995, , , .
4. Others:
For all other data sources like SBDF, excel file, other data tables, add columns/rows,transformations etc. search on "datasource_pro", it will bring similar entries from which number of rows and time taken can be retrieved
DEBUG;2020-05-22T12:39:20,522-07:00;2020-05-22T17:39:20,522;4c72cfcf-a4df-4b42-8d88-91116abc6023;2216154e96uKMs;108;abc;Spotfire.Dxp.Framework.Utilities.ServerLoggerManager;"
Server log manager logged Audit: 2020-05-22T12:39:20,569-06:00, , datasource_pro, execute, True, , Countries, Countries, 1. Select Data > Add... Source: Data table from current analysis Data table: Countries Update behavior: Automatic , 14, 840, ."