You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@openwhisk.apache.org by al...@apache.org on 2020/04/14 00:45:06 UTC
[openwhisk-wskdebug] branch performance created (now fb8194e)
This is an automated email from the ASF dual-hosted git repository.
alexkli pushed a change to branch performance
in repository https://gitbox.apache.org/repos/asf/openwhisk-wskdebug.git.
at fb8194e performance: avoid reading namespace list if not in wskprops, use from initial action GET
This branch includes the following new commits:
new a1d9da2 add debug() logs with DEBUG=wskdebug providing time spent details
new fb8194e performance: avoid reading namespace list if not in wskprops, use from initial action GET
The 2 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[openwhisk-wskdebug] 02/02: performance: avoid reading namespace
list if not in wskprops, use from initial action GET
Posted by al...@apache.org.
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 fb8194e02b2f319c56cbc5da929f56aeceeb3842
Author: Alexander Klimetschek <ak...@adobe.com>
AuthorDate: Mon Apr 13 17:44:15 2020 -0700
performance: avoid reading namespace list if not in wskprops, use from initial action GET
---
src/debugger.js | 45 +++++++++++----------------------------------
1 file changed, 11 insertions(+), 34 deletions(-)
diff --git a/src/debugger.js b/src/debugger.js
index 7343fb6..db33974 100644
--- a/src/debugger.js
+++ b/src/debugger.js
@@ -35,6 +35,7 @@ class Debugger {
constructor(argv) {
this.startTime = Date.now();
debug("starting debugger");
+
this.argv = argv;
this.actionName = argv.action;
@@ -46,11 +47,16 @@ class Debugger {
if (argv.ignoreCerts) {
this.wskProps.ignore_certs = true;
}
+
+ try {
+ this.wsk = openwhisk(this.wskProps);
+ } catch (err) {
+ console.error(`Error: Could not setup openwhisk client: ${err.message}`);
+ process.exit(1);
+ }
}
async start() {
- await this.setupWsk();
-
this.agentMgr = new AgentMgr(this.argv, this.wsk, this.actionName);
this.watcher = new Watcher(this.argv, this.wsk);
@@ -58,13 +64,13 @@ class Debugger {
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");
+ this.wskProps.namespace = actionMetadata.namespace;
+ console.info(`Starting debugger for /${this.wskProps.namespace}/${this.actionName}`);
+
// local debug container
this.invoker = new OpenWhiskInvoker(this.actionName, actionMetadata, this.argv, this.wskProps, this.wsk);
@@ -236,35 +242,6 @@ class Debugger {
this.ready = false;
}
- // ------------------------------------------------< openwhisk utils >------------------
-
- async setupWsk() {
- if (!this.wsk) {
- try {
- this.wsk = openwhisk(this.wskProps);
- } catch (err) {
- console.error(`Error: Could not setup openwhisk client: ${err.message}`);
- process.exit(1);
- }
- if (this.wskProps.namespace === undefined) {
- // there is a strict 1-1 bijection between auth and namespace, hence auth is enough.
- // while the openwhisk() client does not care about the namespace being set,
- // some code here in wskdebug relies on it to be set correctly.
- const namespaces = await this.wsk.namespaces.list();
- if (!namespaces || namespaces.length < 1) {
- console.error("Error: Unknown namespace. Please specify as NAMESPACE in .wskprops.");
- process.exit(2);
- }
- if (namespaces.length > 1) {
- console.error("Error: OpenWhisk reports access to more than one namespace. Please specify the namespace to use as NAMESPACE in .wskprops.", namespaces);
- process.exit(2);
- }
- this.wskProps.namespace = namespaces[0];
- debug(`fetched namespace name: ${this.wskProps.namespace} (was not in wskprops file)`);
- }
- }
- }
-
// ------------------------------------------------< utils >-----------------
async tryCatch(task, message="Error during shutdown:") {
[openwhisk-wskdebug] 01/02: add debug() logs with DEBUG=wskdebug
providing time spent details
Posted by al...@apache.org.
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 <ak...@adobe.com>
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");
}
}