References:
CPS-1126 - Getting issue details... STATUS
Overview :
With previous versions we were able to register 10k cmhandles (in 4 threads) in 12 minutes.
With the current CPS master we sent the 10k cmHandles around 10 minutes to NCMP, so it is not faster than before. What I see is that NCMP starts getting modules in a background thread (seems to be one thread) and handling one cmhandle takes more seconds.
Currenlty in 12 minutes only 150 cmHandles got available with ready state in NCMP, because getting modules and changing the state is quite slow this way.
Expected behavior
With previous versions we were able to register 10k cmhandles (in 4 threads) in 12 minutes.
Reproduction
Register huge amount of cmhandles and try to search them.
After 12 minutes there were only ~150cmHandles inready state
Analyzed the logs the summary is as below :
Patch used for testing :
https://gerrit.onap.org/r/c/cps/+/129829/5//COMMIT_MSG
Configurations:
| # | Configuration | Description |
|---|---|---|
| 1 | Number of CPS Instance | 1 |
| 2 | Total number of threads to send each batch (Register cm handle) | 4 |
| 3 | Batch size | 100 |
| 4 | To register 1458 cm handles | Used to send 15 batchs (100 cm handles in each batch) |
| # | Watchdog | Fixed Delay String (in ms) |
|---|---|---|
| 1 | timers: advised-modules-sync: sleep-time-ms: | 30000 |
| 2 | timers: locked-modules-sync: sleep-time-ms: | 300000 |
| 3 | timers: cm-handle-data-sync: sleep-time-ms: | 30000 |
| # | Data Sync | Enabled ? |
|---|---|---|
| 1 | data-sync: cache: enabled: | false |
Scenario 1: If there is no cm handle into Advised state
Average time elapsed to get/fetch cm handles by state ADVISED is ~ 3-4 ms
CPS -log :
2022-07-15 04:40:17.918 INFO [cps-application,57eae02b31a98818,57eae02b31a98818] 1 --- [ watchdog-th-9] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get cm handles by state ADVISED is : 3 ms | Fetched data node size is 0 2022-07-15 04:40:17.918 INFO [cps-application,57eae02b31a98818,57eae02b31a98818] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : No Cm-Handles currently found in an ADVISED state 2022-07-15 04:40:48.003 INFO [cps-application,e1fb65c00a949ce0,e1fb65c00a949ce0] 1 --- [ watchdog-th-9] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get cm handles by state ADVISED is : 4 ms | Fetched data node size is 0 2022-07-15 04:40:48.003 INFO [cps-application,e1fb65c00a949ce0,e1fb65c00a949ce0] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : No Cm-Handles currently found in an ADVISED state
Scenario 2: If we started registering 1458 with configuration mentioned above :
| # | Operations | Average Time elapsed (in ~ ms) | |||
|---|---|---|---|---|---|
| 1 | To save cm handle state with id | Batch #.Iteration # | Time elapsed (in ~ ms) | ||
| 1.1 | 293 | ||||
| 1.2 | 84 | ||||
| 2.1 | 14 | ||||
| 2.2 | 8 | ||||
| Average Time elapsed per cm handle (in ~ ms) | 53 | ||||
| 2 | To synchronize, create schema set and anchor with id | Batch #.Iteration # | Time elapsed (in ~ ms) | ||
| 1.1 | 38393 | ||||
| 1.2 | 599 | ||||
| 2.1 | 237 | ||||
| 2.2 | 122 | ||||
| Average Time elapsed per cm handle (in ~ ms) | 19675.5 | ||||
| 3 | Delete schema set If exists with id | Batch #.Iteration # | Time elapsed (in ~ ms) | ||
| 1.1 | 17 | ||||
| 1.2 | 2 | ||||
| 2.1 | 2 | ||||
| 2.2 | 2 | ||||
| Average Time elapsed per cm handle (in ~ ms) | 11.5 | ||||
| 4 | Get cm handle state with id | Batch #.Iteration # | Time elapsed (in ~ ms) | ||
| 1.1 | 83 | ||||
| 1.2 | 7 | ||||
| 2.1 | 10 | ||||
| 2.2 | 12 | ||||
| Average Time elapsed per cm handle (in ~ ms) | 56 | ||||
| 5 | To get yang models | Batch # | Batch Size | Time elapsed (in ~ ms) | Time elapsed per cm handle (in ~ ms) |
| 1 | 601 | 63107 | 105.00 | ||
| 2 | 857 | 37337 | 43.56 | ||
| Average Time elapsed per iteration (in ~ ms) | 74.28 | ||||
| 6 | To shuffle cm handles | Batch # | Batch Size | Time elapsed (in ~ ms) | |
| 1 | 601 | 0 | |||
| 2 | 857 | 0 | |||
| Average Time elapsed per iteration (in ~ ms) | 0 | ||||
| 7 | Get / fetch cm handles by state ADVISED | Batch # | Batch Size | Time elapsed (in ~ ms) | Time elapsed per cm handle (in ~ ms) |
| 1 | 601 | 19404 | 32.28 | ||
| 2 | 857 | 3485 | 4.06 | ||
| Average Time elapsed per iteration (in ~ ms) | 18.17 | ||||
| # | Operation | Time |
|---|---|---|
| 1 | Registration of 1458 cm handles started | 04:41:00 |
| 2 | 1st ADVISED cm handle with B031D6DDF9AA4CA484727B7A497AB27D | 2022-07-15T04:40:49.307+0000 |
| 3 | 1458th ADVISED cm handle with BFAB827B9CC652EE60DD2545D55EF0CA | 2022-07-15T04:41:58.018+0000 |
| 4 | 1st READY cm handle with 47C5F63DFF44436A6C56AC684B5E48C7 | 2022-07-15T04:40:49.307+0000 |
| 5 | 1458th READY cm handle with BFAB827B9CC652EE60DD2545D55EF0CA | 2022-07-15T04:41:58.018+0000 |
Average time to make all 1458 cm handles from ADVICED to READY state is: ~ 10 minutes
First Batch:
First iteration:
2022-07-15 04:41:37.407 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get cm handles by state ADVISED is : 19404 ms | Fetched data node size is 601 2022-07-15 04:41:37.408 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to shuffle advisedCmHandles list of size : 601 is 0 ms 2022-07-15 04:42:40.516 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get yang model cm handles is : 63107 ms 2022-07-15 04:42:40.600 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to get cm handle state with id 6D3F803EFCCB92F84FEE3CAEEEC0C48D is : 83 ms 2022-07-15 04:42:40.618 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to deleteSchemaSetIfExists with id 6D3F803EFCCB92F84FEE3CAEEEC0C48D is : 17 ms 2022-07-15 04:43:19.011 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to syncAndCreateSchemaSetAndAnchor with id 6D3F803EFCCB92F84FEE3CAEEEC0C48D is : 38393 ms 2022-07-15 04:43:19.307 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to executeAdvisedCmHandlePoll saveCmHandleState with id 6D3F803EFCCB92F84FEE3CAEEEC0C48D is : 293 ms 2022-07-15 04:43:19.307 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : 6D3F803EFCCB92F84FEE3CAEEEC0C48D is now in READY state
Second iteration :
2022-07-15 04:43:19.314 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to get cm handle state with id CA29889D3AE24486DD95344AEC60E0F7 is : 7 ms 2022-07-15 04:43:19.317 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to deleteSchemaSetIfExists with id CA29889D3AE24486DD95344AEC60E0F7 is : 2 ms 2022-07-15 04:43:19.916 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to syncAndCreateSchemaSetAndAnchor with id CA29889D3AE24486DD95344AEC60E0F7 is : 599 ms 2022-07-15 04:43:20.001 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to executeAdvisedCmHandlePoll saveCmHandleState with id CA29889D3AE24486DD95344AEC60E0F7 is : 84 ms 2022-07-15 04:43:20.001 INFO [cps-application,8ffa50adfe3fb407,8ffa50adfe3fb407] 1 --- [ watchdog-th-9] o.o.c.n.a.i.sync.ModuleSyncWatchdog : CA29889D3AE24486DD95344AEC60E0F7 is now in READY state
Second Batch:
First iteration:
2022-07-15 04:45:51.513 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get cm handles by state ADVISED is : 3485 ms | Fetched data node size is 857 2022-07-15 04:45:51.513 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to shuffle advisedCmHandles list of size : 857 is 0 ms 2022-07-15 04:46:28.851 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.ncmp.api.inventory.sync.SyncUtils : Time elapsed to get yang model cm handles is : 37337 ms 2022-07-15 04:46:28.861 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to get cm handle state with id F11218269B0D31012FBAFF88F9B4A345 is : 10 ms 2022-07-15 04:46:28.864 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to deleteSchemaSetIfExists with id F11218269B0D31012FBAFF88F9B4A345 is : 2 ms 2022-07-15 04:46:29.101 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to syncAndCreateSchemaSetAndAnchor with id F11218269B0D31012FBAFF88F9B4A345 is : 237 ms 2022-07-15 04:46:29.116 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to executeAdvisedCmHandlePoll saveCmHandleState with id F11218269B0D31012FBAFF88F9B4A345 is : 14 ms 2022-07-15 04:46:29.116 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : F11218269B0D31012FBAFF88F9B4A345 is now in READY state
Second iteration:
2022-07-15 04:46:29.128 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to get cm handle state with id D79ADF6E3AE62A2D450BEB0F14565EE1 is : 12 ms 2022-07-15 04:46:29.131 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to deleteSchemaSetIfExists with id D79ADF6E3AE62A2D450BEB0F14565EE1 is : 2 ms 2022-07-15 04:46:29.254 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to syncAndCreateSchemaSetAndAnchor with id D79ADF6E3AE62A2D450BEB0F14565EE1 is : 122 ms 2022-07-15 04:46:29.262 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : Time elapsed to executeAdvisedCmHandlePoll saveCmHandleState with id D79ADF6E3AE62A2D450BEB0F14565EE1 is : 8 ms 2022-07-15 04:46:29.262 INFO [cps-application,acf4595802b71109,acf4595802b71109] 1 --- [ watchdog-th-10] o.o.c.n.a.i.sync.ModuleSyncWatchdog : D79ADF6E3AE62A2D450BEB0F14565EE1 is now in READY state