This is an automated email from the ASF dual-hosted git repository. alexkli pushed a commit to branch performance in repository https://gitbox.apache.org/repos/asf/openwhisk-wskdebug.git
commit a1d9da2af64a6e2e7f87a11431fa298f82bd23df Author: Alexander Klimetschek <[email protected]> AuthorDate: Mon Apr 13 17:02:01 2020 -0700 add debug() logs with DEBUG=wskdebug providing time spent details --- index.js | 2 ++ package-lock.json | 54 +++++++++++++++++++++++++++++++++++++++++++++++++++--- package.json | 3 +++ src/agentmgr.js | 10 ++++++++++ src/debug.js | 21 +++++++++++++++++++++ src/debugger.js | 31 +++++++++++++++++++++++++++++-- src/invoker.js | 21 ++++++++++++++------- src/watcher.js | 2 ++ 8 files changed, 132 insertions(+), 12 deletions(-) diff --git a/index.js b/index.js index 0406efe..18d13ff 100644 --- a/index.js +++ b/index.js @@ -21,6 +21,7 @@ const yargs = require("yargs"); const Debugger = require("./src/debugger"); const path = require("path"); const fs = require("fs"); +const debug = require('./src/debug'); function enableConsoleColors() { // colorful console.error() and co @@ -286,6 +287,7 @@ function registerExitHandler(dbg) { } async function wskdebug(args, isCommandLine=false) { + debug("wskdebug arguments:", args); const originalConsole = enableConsoleColors(); try { diff --git a/package-lock.json b/package-lock.json index 28b394f..00a4067 100644 --- a/package-lock.json +++ b/package-lock.json @@ -655,9 +655,9 @@ } }, "debug": { - "version": "3.2.6", - "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz";, - "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==", + "version": "4.1.1", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.1.1.tgz";, + "integrity": "sha512-pYAIzeRo8J6KPEaJ0VWOh5Pzkbw/RetuzehGM7QRRX5he4fPHx2rdKMB256ehJCkX+XRQm16eZLqLNS8RSZXZw==", "requires": { "ms": "^2.1.1" } @@ -1938,6 +1938,15 @@ "integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU=", "dev": true }, + "debug": { + "version": "3.2.6", + "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz";, + "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==", + "dev": true, + "requires": { + "ms": "^2.1.1" + } + }, "emoji-regex": { "version": "7.0.3", "resolved": "https://registry.npmjs.org/emoji-regex/-/emoji-regex-7.0.3.tgz";, @@ -2106,6 +2115,17 @@ "requires": { "debug": "^3.1.0", "lodash": "^4.16.4" + }, + "dependencies": { + "debug": { + "version": "3.2.6", + "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz";, + "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==", + "dev": true, + "requires": { + "ms": "^2.1.1" + } + } } }, "mock-require": { @@ -2160,6 +2180,16 @@ "debug": "^3.2.6", "iconv-lite": "^0.4.4", "sax": "^1.2.4" + }, + "dependencies": { + "debug": { + "version": "3.2.6", + "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz";, + "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==", + "requires": { + "ms": "^2.1.1" + } + } } }, "nice-try": { @@ -2419,6 +2449,11 @@ "callsites": "^3.0.0" } }, + "parse-ms": { + "version": "2.1.0", + "resolved": "https://registry.npmjs.org/parse-ms/-/parse-ms-2.1.0.tgz";, + "integrity": "sha512-kHt7kzLoS9VBZfUsiKjv43mr91ea+U05EyKkEtqp7vNbHxmaVuEqN7XxeEVnGrMtYOAxGrDElSi96K7EgO1zCA==" + }, "path-exists": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/path-exists/-/path-exists-4.0.0.tgz";, @@ -2462,6 +2497,19 @@ "integrity": "sha1-IZMqVJ9eUv/ZqCf1cOBL5iqX2lQ=", "dev": true }, + "pretty-bytes": { + "version": "5.3.0", + "resolved": "https://registry.npmjs.org/pretty-bytes/-/pretty-bytes-5.3.0.tgz";, + "integrity": "sha512-hjGrh+P926p4R4WbaB6OckyRtO0F0/lQBiT+0gnxjV+5kjPBrfVBFCsCLbMqVQeydvIoouYTCmmEURiH3R1Bdg==" + }, + "pretty-ms": { + "version": "6.0.1", + "resolved": "https://registry.npmjs.org/pretty-ms/-/pretty-ms-6.0.1.tgz";, + "integrity": "sha512-ke4njoVmlotekHlHyCZ3wI/c5AMT8peuHs8rKJqekj/oR5G8lND2dVpicFlUz5cbZgE290vvkMuDwfj/OcW1kw==", + "requires": { + "parse-ms": "^2.1.0" + } + }, "process-on-spawn": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/process-on-spawn/-/process-on-spawn-1.0.0.tgz";, diff --git a/package.json b/package.json index 6aa1af5..b717ddf 100644 --- a/package.json +++ b/package.json @@ -42,12 +42,15 @@ "file": "test/logfile.setup.js" }, "dependencies": { + "debug": "^4.1.1", "fetch-retry": "^3.1.0", "fs-extra": "^8.1.0", "isomorphic-fetch": "^2.2.1", "livereload": "^0.9.1", "manakin": "^0.5.2", "openwhisk": "^3.21.1", + "pretty-bytes": "^5.3.0", + "pretty-ms": "^6.0.1", "yargs": "^15.3.1" }, "peerDependencies": { diff --git a/src/agentmgr.js b/src/agentmgr.js index ecf33a2..1806c05 100644 --- a/src/agentmgr.js +++ b/src/agentmgr.js @@ -27,6 +27,7 @@ try { const fs = require('fs-extra'); const sleep = require('util').promisify(setTimeout); +const debug = require('./debug'); function getAnnotation(action, key) { const a = action.annotations.find(a => a.key === key); @@ -76,6 +77,7 @@ async function deleteActionIfExists(wsk, name) { if (await actionExists(wsk, name)) { await wsk.actions.delete(name); } + debug(`restore: ensured removal of action ${name}`); } @@ -170,6 +172,7 @@ class AgentMgr { // agent using ngrok for forwarding agentName = "ngrok"; agentCode = await this.ngrokAgent.getAgent(action); + debug("started local ngrok proxy"); } else { this.concurrency = await this.openwhiskSupports("concurrency"); @@ -197,6 +200,7 @@ class AgentMgr { name: backupName, action: action }); + debug(`created action backup ${backupName}`); if (this.argv.verbose) { console.log(`Original action backed up at ${backupName}.`); @@ -220,6 +224,7 @@ class AgentMgr { await this.pushAgent(action, agentCode, backupName); } } + debug(`installed agent (${agentName}) in place of ${this.actionName}`); if (this.argv.verbose) { console.log(`Agent installed.`); @@ -238,6 +243,7 @@ class AgentMgr { } finally { if (this.ngrokAgent) { await this.ngrokAgent.stop(); + debug("ngrok shut down"); } } } @@ -404,15 +410,18 @@ class AgentMgr { try { // the original was backed up in the copy const original = await this.wsk.actions.get(copy); + debug("restore: fetched action original from backup copy (move step 1)"); // copy the backup (copy) to the regular action await this.wsk.actions.update({ name: this.actionName, action: original }); + debug("restore: restored action with original (move step 2)"); // remove the backup await this.wsk.actions.delete(copy); + debug("restore: deleted backup copy (move step 3)"); // remove any helpers if they exist await deleteActionIfExists(this.wsk, `${this.actionName}_wskdebug_invoked`); @@ -492,6 +501,7 @@ class AgentMgr { ] } }); + debug(`created helper action ${actionName}`); } // ----------------------------------------< openwhisk feature detection >----------------- diff --git a/src/debug.js b/src/debug.js new file mode 100644 index 0000000..6e4cc49 --- /dev/null +++ b/src/debug.js @@ -0,0 +1,21 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +'use strict'; + +// common debug() instance for shared time spent measurments (+millis) +module.exports = require('debug')('wskdebug'); diff --git a/src/debugger.js b/src/debugger.js index 3bf6433..7343fb6 100644 --- a/src/debugger.js +++ b/src/debugger.js @@ -24,12 +24,17 @@ const Watcher = require('./watcher'); const openwhisk = require('openwhisk'); const { spawnSync } = require('child_process'); const sleep = require('util').promisify(setTimeout); +const debug = require('./debug'); +const prettyBytes = require('pretty-bytes'); +const prettyMilliseconds = require('pretty-ms'); /** * Central component of wskdebug. */ class Debugger { constructor(argv) { + this.startTime = Date.now(); + debug("starting debugger"); this.argv = argv; this.actionName = argv.action; @@ -51,12 +56,15 @@ class Debugger { // quick fail for missing requirements such as docker not running await OpenWhiskInvoker.checkIfAvailable(); + debug("verified that docker is available and running"); console.info(`Starting debugger for /${this.wskProps.namespace}/${this.actionName}`); // get the action metadata const actionMetadata = await this.agentMgr.peekAction(); + debug("fetched action metadata from openwhisk"); + // local debug container this.invoker = new OpenWhiskInvoker(this.actionName, actionMetadata, this.argv, this.wskProps, this.wsk); @@ -70,10 +78,17 @@ class Debugger { // start container - get it up fast for VSCode to connect within its 10 seconds timeout await this.invoker.startContainer(); + debug(`started container: ${this.invoker.name()}`); + // get code and /init local container const actionWithCode = await this.agentMgr.readActionWithCode(); + + debug(`fetched action code from openwhisk (${prettyBytes(actionWithCode.exec.code.length)})`); + await this.invoker.init(actionWithCode); + debug("installed action on container (/init)"); + // setup agent in openwhisk await this.agentMgr.installAgent(actionWithCode, this.invoker); @@ -87,10 +102,17 @@ class Debugger { console.log(); console.info(`Action : ${this.actionName}`); - this.invoker.logInfo(); + if (this.sourcePath) { + console.info(`Sources : ${this.invoker.getSourcePath()}`); + } + console.info(`Image : ${this.invoker.getImage()}`); + console.info(`Container : ${this.invoker.name()}`); + console.info(`Debug type : ${this.invoker.getDebugKind()}`); + console.info(`Debug port : localhost:${this.invoker.getPort()}`); if (this.argv.condition) { console.info(`Condition : ${this.argv.condition}`); } + console.info(`Startup : ${prettyMilliseconds(Date.now() - this.startTime)}`) console.log(); console.info(`Ready, waiting for activations! Use CTRL+C to exit`); @@ -183,6 +205,8 @@ class Debugger { return; } this.shuttingDown = true; + const shutdownStart = Date.now(); + debug("shutting down..."); // only log this if we started properly if (this.ready) { @@ -198,14 +222,16 @@ class Debugger { } if (this.invoker) { await this.tryCatch(this.invoker.stop()); + debug(`stopped container: ${this.invoker.name()}`); } if (this.watcher) { await this.tryCatch(this.watcher.stop()); + debug("stopped source file watching"); } // only log this if we started properly if (this.ready) { - console.log(`Done`); + console.log(`Done (shutdown took ${prettyMilliseconds(Date.now() - shutdownStart)})`); } this.ready = false; } @@ -234,6 +260,7 @@ class Debugger { process.exit(2); } this.wskProps.namespace = namespaces[0]; + debug(`fetched namespace name: ${this.wskProps.namespace} (was not in wskprops file)`); } } } diff --git a/src/invoker.js b/src/invoker.js index f2fe6dc..9a92318 100644 --- a/src/invoker.js +++ b/src/invoker.js @@ -241,13 +241,20 @@ class OpenWhiskInvoker { }); } - async logInfo() { - if (this.sourcePath) { - console.info(`Sources : ${this.sourcePath}`); - } - console.info(`Image : ${this.image}`); - console.info(`Debug type : ${this.debugKind}`); - console.info(`Debug port : localhost:${this.debug.port}`) + getSourcePath() { + return this.sourcePath; + } + + getImage() { + return this.image; + } + + getDebugKind() { + return this.debugKind; + } + + getPort() { + return this.debug.port; } async init(actionWithCode) { diff --git a/src/watcher.js b/src/watcher.js index 4e0fd91..dcea5a6 100644 --- a/src/watcher.js +++ b/src/watcher.js @@ -20,6 +20,7 @@ const fs = require('fs-extra'); const livereload = require('livereload'); const { spawnSync } = require('child_process'); +const debug = require('./debug'); class Watcher { constructor(argv, wsk) { @@ -105,6 +106,7 @@ class Watcher { if (this.argv.livereload) { console.info(`LiveReload enabled for ${watch} on port ${this.liveReloadServer.config.port}`); } + debug("started source file watching"); } }
