Add debug timer to creator node app initialization

[endline]

Description

We want to hone in on why creator nodes take so long to initialize

Tests

# up the stack
audius-compose up

# tail creator logs
docker compose logs -f creator-node | grep debugLogTimer

i.e.

$ docker compose logs -f creator-node | grep debugLogTimer

docker compose logs creator-node -f | grep LogTimer
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"master","hostname":"08fc9d3e134a","pid":343,"level":20,"msg":"LogTimer: startAppForPrimary                      - 0s","time":"2022-11-08T19:58:35.191Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"master","hostname":"806c58e415b4","pid":337,"level":20,"msg":"LogTimer: startAppForPrimary                      - 0s","time":"2022-11-08T19:58:32.864Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"master","hostname":"6c2e81371ca0","pid":335,"level":20,"msg":"LogTimer: startAppForPrimary                      - 0s","time":"2022-11-08T19:58:34.105Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"master","hostname":"c1b02780ba88","pid":342,"level":20,"msg":"LogTimer: startAppForPrimary                      - 0s","time":"2022-11-08T19:58:34.430Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startAppForWorker                       - 0s","time":"2022-11-08T20:00:40.263Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.001s","time":"2022-11-08T20:00:40.263Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startAppForWorker.startApp              - 1.236s","time":"2022-11-08T20:00:41.498Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startApp.serviceRegistry.initServices   - 1.241s","time":"2022-11-08T20:00:41.503Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startAppForWorker                       - 0s","time":"2022-11-08T20:00:43.525Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.001s","time":"2022-11-08T20:00:43.526Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startAppForWorker.startApp              - 1.029s","time":"2022-11-08T20:00:44.554Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startApp.serviceRegistry.initServices   - 1.031s","time":"2022-11-08T20:00:44.556Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startAppForWorker                       - 0.001s","time":"2022-11-08T20:00:47.511Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.002s","time":"2022-11-08T20:00:47.512Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startApp.initializeApp                  - 7.687s","time":"2022-11-08T20:00:47.949Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startAppForWorker.startApp              - 0.7s","time":"2022-11-08T20:00:48.210Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startApp.serviceRegistry.initServices   - 0.706s","time":"2022-11-08T20:00:48.216Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startAppForWorker                       - 0.001s","time":"2022-11-08T20:00:51.351Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.005s","time":"2022-11-08T20:00:51.355Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startApp.initializeApp                  - 8.289s","time":"2022-11-08T20:00:51.814Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startAppForWorker.startApp              - 0.838s","time":"2022-11-08T20:00:52.188Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startApp.serviceRegistry.initServices   - 0.841s","time":"2022-11-08T20:00:52.191Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startApp.initializeApp                  - 7.422s","time":"2022-11-08T20:00:54.932Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startApp.initializeApp                  - 6.517s","time":"2022-11-08T20:00:57.867Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-4  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"806c58e415b4","pid":489,"level":20,"msg":"LogTimer: startApp.initialized                    - 37.433s","time":"2022-11-08T20:01:17.695Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-1  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"6c2e81371ca0","pid":487,"level":20,"msg":"LogTimer: startApp.initialized                    - 35.503s","time":"2022-11-08T20:01:19.028Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-2  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"08fc9d3e134a","pid":490,"level":20,"msg":"LogTimer: startApp.initialized                    - 36.059s","time":"2022-11-08T20:01:23.569Z","v":0,"logLevel":"debug"}
audius-protocol-creator-node-3  | {"name":"audius_creator_node","clusterWorker":"Worker 1","hostname":"c1b02780ba88","pid":497,"level":20,"msg":"LogTimer: startApp.initialized                    - 34.392s","time":"2022-11-08T20:01:25.742Z","v":0,"logLevel":"debug"}

can go crazy if you like

$ docker compose logs creator-node -f | grep LogTimer | awk -F'|' '{print $2}' | jq -r .msg

"LogTimer: startAppForPrimary                      - 0s"
"LogTimer: startAppForPrimary                      - 0s"
"LogTimer: startAppForPrimary                      - 0s"
"LogTimer: startAppForPrimary                      - 0s"
"LogTimer: startAppForWorker                       - 0s"
"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.001s"
"LogTimer: startAppForWorker.startApp              - 1.236s"
"LogTimer: startApp.serviceRegistry.initServices   - 1.241s"
"LogTimer: startAppForWorker                       - 0s"
"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.001s"
"LogTimer: startAppForWorker.startApp              - 1.029s"
"LogTimer: startApp.serviceRegistry.initServices   - 1.031s"
"LogTimer: startAppForWorker                       - 0.001s"
"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.002s"
"LogTimer: startApp.initializeApp                  - 7.687s"
"LogTimer: startAppForWorker.startApp              - 0.7s"
"LogTimer: startApp.serviceRegistry.initServices   - 0.706s"
"LogTimer: startAppForWorker                       - 0.001s"
"LogTimer: startAppForWorker.verifyConfigAndDb     - 0.005s"
"LogTimer: startApp.initializeApp                  - 8.289s"
"LogTimer: startAppForWorker.startApp              - 0.838s"
"LogTimer: startApp.serviceRegistry.initServices   - 0.841s"
"LogTimer: startApp.initializeApp                  - 7.422s"
"LogTimer: startApp.initializeApp                  - 6.517s"
"LogTimer: startApp.initialized                    - 37.433s"
"LogTimer: startApp.initialized                    - 35.503s"
"LogTimer: startApp.initialized                    - 36.059s"
"LogTimer: startApp.initialized                    - 34.392s"

[endline]

@dmanjunath thinking i should add more granular calls to debugLogTimer to make this moar useful

[dmanjunath]

@endline maybe a few more would be useful particularly in startAppForWorker and startApp but even without that it's good to know that it takes 25 seconds locally which i had no idea about

[endline]

would like to add to this in a follow up PR to capture the container entrypoint and bash scripts