How to enable debugging output for Portfolio Sync Job

Document ID : KB000029109
Last Modified Date : 14/02/2018
Show Technical Document Details

To enable Portfolio Sync Job diagnostic profile logging the following procedure should be followed:

1. Make sure that the Portfolio Sync Job is not running.
2. If the user has ‘admin’ privileges, then access the logger configuration pages either from the CSA or the PPM application as follows:
CSA:
a.  If CSA is running and accessible, login.
b.  Click on the appropriate <server> link under the ‘Server’ list to get the properties page listing.
c.  Navigate to the ‘Logs’, ’Edit Configuration’ page.
APP:
a.  As an administrator user, login to the PPM application
b.  Type in the following url: <server>:<port>/niku/nu#action:security.logs
c.  Use the drop down ‘Logs’ tab to choose ‘Edit Configuration’ 
3. On the logger configuration page two appenders and two categories must be added to the logger configuration as follows:
Add the appenders: 
a.  In the appender section select the ‘STDOUT’ appender by checking the box next to it and click the ‘Copy Appender’ button, then click the ‘Save’ button.
b.  Change the name of the new appender ‘PFMHeader’.
c.  Change the file of the new appender to ../logs/pfmprofile.log
d.  Click the ‘Save’ button.
e.  In the appender section select the ‘STDOUT’ appender by checking the box next to it and click the ‘Copy Appender’ button, then click the ‘Save’ button.
f.  Change the name of the new appender ‘PFMProfile’.
g.  Change the file of the new appender to ../logs/pfmprofile.log
h.  Change the Conversion Pattern to be: ="%-5p %d{ISO8601} %m\r\n"
i.  Click the ‘Save’ button.
Add the categories:  
a.  In the categories section, click the ‘Add Category’ button. This will add a category to the bottom of the list with the name ‘com.niku’.
b.  Change the name by populating the ‘Other Name’ field with ‘portfolio.sync.header’
c.  Set the appender to the newly created ‘PFMHeader’ appender.
d.  Set the priority to ‘DEBUG’.
e.  Leave the ‘Additive’ checkbox unchecked.
f.  Click the ‘Save’ button.
g.  In the categories section, click the ‘Add Category’ button. This will add a category to the bottom of the list with the name ‘com.niku’.
h.  Change the name by populating the ‘Other Name’ field with ‘portfolio.sync.profile’
i.  Set the appender to the newly created ‘PFMProfile’ appender.
j.  Set the priority to ‘WARN.
k.  Leave the ‘Additive’ checkbox unchecked.
l.  Click the ‘Save’ button.
4. To start logging for the PFM Portfolio Synchronization Job change the priority for the ‘portfolio.sync.profile’ category to either ‘DEBUG’ or ‘TRACE’. The ‘TRACE’ priority will log more details regarding the operation of the PFM Portfolio Synchronization Job. 
5. If the PPM Application(app) Server and Background(bg) Server are not running, start them. If the bg server is already running you will need to restart it if the checkbox ‘Detect Log Configuration Changes Automatically’ is not checked in the logs configuration page.
6. Start the Portfolio Synchronization Job by selecting a portfolio in the PPM Application.  In the Content Editor page or Target Worksheet page, click on the ‘Sync Now’ button. Alternatively schedule the Job via the Jobs Scheduler pages in the PPM Application.
7. After the job has finished and profile logging is no longer desired, to disable logging, change the priority back to ‘WARN’  in the  ‘portfolio.sync.profile’ category. The same consideration for restarting the bg server will need to be adhered to if the logger configuration is not set to be automatically detected as described above.
8. To view the logged information from running of the PFM Portfolio Synchronization Job locate the output log file ‘bg-pfmprofile.log’ in the logs directory.
 
Example log file content:  
DEBUG 2014-11-25 16:20:47,794 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncManager.run, Begin Sync: Portfolio Id = 5000001
DEBUG 2014-11-25 16:20:47,819 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncManager.run Create temp tables: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:01,771 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncManager.run Clear temp tables: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:01,871 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncDataManager.preCheck: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:01,871 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncDataManager.getSyncHandlers: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:01,877 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncDataManager perform doSync with handlers: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:12,020 [Dispatch pool-5-thread-4 : bg (tenant=clarity)] sync.header (clarity:admin:5303557__8183F05C-74CB-476C-B0D2-327CCC9E0E64:Synchronize portfolio investments) PFMSyncDataManager.postSync: Portfolio Id = 5000001
DEBUG 2014-11-25 16:21:14,885  
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMInvSyncHandler.doSync:service - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMInvSyncHandler.performSyncTasks.stmtmgr.processMVL: project - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 287ms - 1 - 1.06%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMRoleSyncHandler.persistRoleDemand roleAggUtil_.persistRoleDemand() - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 163ms - 1 - 0.60%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMInvSyncHandler.doSync:asset - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 725ms - 1 - 2.68%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMSyncManager.run Instantiation of PFMSyncDataManager - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 25ms - 1 - 0.09%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMRoleSyncHandler.aggregateCosts roleAggUtil_.persistCosts() - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 325ms - 1 - 1.20%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMSyncDataManager.postSync Initialize the ranking contexts - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 327ms - 1 - 1.21%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMSyncDataManager.postSync stmtMgr_.executeDelete() - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMInvSyncHandler.performSyncTasks.datamgr.prfinishSync: project - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 799ms - 1 - 2.95%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMSyncDataManager.postSync copyBaselineData(portfolioId_) - 
DEBUG 2014-11-25 16:21:14,885 ---Timer--- 46ms - 1 - 0.17%
DEBUG 2014-11-25 16:21:14,885 ---Timer--- PFMInvSyncHandler.doSync:application - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 636ms - 1 - 2.35%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncManager.run Clear temp tables - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 99ms - 1 - 0.37%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.postSync new SyncSliceService( stmtMgr_.getContext(), portInt ) - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 950ms - 1 - 3.51%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.finishSync finCostAPI.getFMCosts() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 656ms - 1 - 2.42%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.performSyncTasks.datamgr.prfinishSync: asset - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 208ms - 1 - 0.77%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.preCheck - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.getSyncHandlers - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 6ms - 1 - 0.02%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.doSync:project - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 5057ms - 1 - 18.67%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager dataMgr.persisCostInfo() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 661ms - 1 - 2.44%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.finishSync stmtMgr_.processPFMData() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 1173ms - 3 - 4.33%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.performSyncTasks.datamgr.prfinishSync: application - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 169ms - 1 - 0.62%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.doAggregation roleAggUtil_.demandAgg() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 3057ms - 1 - 11.28%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.performSyncTasks.stmtmgr.processMVL: application - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 87ms - 1 - 0.32%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.postSync stmtMgr_.deleteOrphanRoleDemand() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 28ms - 1 - 0.10%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.doSync:idea - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.doSync:other - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.postSync stmtMgr_.bootstrapPFM_ROLE_DEMAND() - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 0ms - 1 - 0.00%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.postSync - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 2865ms - 1 - 10.58%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMRoleSyncHandler.aggregateCosts roleAggUtil_.aggregateCosts(fmCostMap) - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 2ms - 1 - 0.01%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.doSync:product - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 7ms - 1 - 0.03%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMInvSyncHandler.performSyncTasks.stmtmgr.processMVL: asset - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 127ms - 1 - 0.47%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncManager.run Create temp tables - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 13952ms - 1 - 51.50%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- PFMSyncDataManager.finishSync Instantiation of PFMFinCostSyncHandler - 
DEBUG 2014-11-25 16:21:14,886 ---Timer--- 5ms - 1 - 0.02%
DEBUG 2014-11-25 16:21:14,886 ---Timer--- Total - 27091
DEBUG 2014-11-25 16:21:14,886