Fix #939 Allow messages to display run time for each batch when there are multiple batches (#943)

* Fix  #939 Allow messages to display run time for each batch when there are multiple batches
- Added this feature behind a config flag
- Some time parsing fixes to support this

localization/xliff/enu/constants/localizedConstants.enu.xlf

@@ -287,6 +287,9 @@
         <trans-unit id="disconnectConfirmationMsg">
             <source xml:lang="en">Are you sure you want to disconnect?</source>
         </trans-unit>
+        <trans-unit id="elapsedBatchTime">
+            <source xml:lang="en">Batch execution time: {0}</source>
+        </trans-unit>
         <trans-unit id="noActiveEditorMsg">
             <source xml:lang="en">A SQL editor must have focus before executing this command</source>
         </trans-unit>

package.json

@@ -468,6 +468,11 @@
           "description": "[Optional] Configuration options for copying multi-line results from the Results View",
           "default": true
         },
+        "mssql.showBatchTime": {
+          "type": "boolean",
+          "description": "[Optional] Should execution time be shown for individual batches",
+          "default": false
+        },
         "mssql.splitPaneSelection": {
           "type": "string",
           "description": "[Optional] Configuration options for which column new result panes should open in",

src/constants/constants.ts

@@ -63,6 +63,7 @@ export const configRecentConnections = 'recentConnections';
 export const configMaxRecentConnections = 'maxRecentConnections';
 export const configCopyRemoveNewLine = 'copyRemoveNewLine';
 export const configSplitPaneSelection = 'splitPaneSelection';
+export const configShowBatchTime = 'showBatchTime';
 export const extConfigResultKeys = ['shortcuts', 'messagesDefaultOpen'];
 export const sqlToolsServiceInstallDirConfigKey = 'installDir';
 export const sqlToolsServiceExecutableFilesConfigKey = 'executableFiles';

src/controllers/queryRunner.ts

@@ -14,7 +14,7 @@ import { BatchSummary, QueryExecuteParams, QueryExecuteRequest,
     QueryExecuteBatchNotificationParams } from '../models/contracts/queryExecute';
 import { QueryDisposeParams, QueryDisposeRequest } from '../models/contracts/queryDispose';
 import { QueryCancelParams, QueryCancelResult, QueryCancelRequest } from '../models/contracts/queryCancel';
-import { ISlickRange, ISelectionData } from '../models/interfaces';
+import { ISlickRange, ISelectionData, IResultMessage } from '../models/interfaces';
 import Constants = require('../constants/constants');
 import LocalizedConstants = require('../constants/localizedConstants');
 import * as Utils from './../models/utils';
@@ -213,7 +213,12 @@ export default class QueryRunner {
 
         // Store the batch again to get the rest of the data
         this._batchSets[batch.id] = batch;
-        this._totalElapsedMilliseconds += <number>(Utils.parseTimeString(batch.executionElapsed) || 0);
+        let executionTime = <number>(Utils.parseTimeString(batch.executionElapsed) || 0);
+        this._totalElapsedMilliseconds += executionTime;
+        if (executionTime > 0) {
+            // send a time message in the format used for query complete
+            this.sendBatchTimeMessage(batch.id, Utils.parseNumAsTimeString(executionTime));
+        }
         this.eventEmitter.emit('batchComplete', batch);
     }
 
@@ -364,6 +369,22 @@ export default class QueryRunner {
         return outputString;
     }
 
+    private sendBatchTimeMessage(batchId: number, executionTime: string): void {
+        // get config copyRemoveNewLine option from vscode config
+        let config = this._vscodeWrapper.getConfiguration(Constants.extensionConfigSectionName);
+        let showBatchTime: boolean = config[Constants.configShowBatchTime];
+        if (showBatchTime) {
+            let message: IResultMessage = {
+                batchId: batchId,
+                message: Utils.formatString(LocalizedConstants.elapsedBatchTime, executionTime),
+                time: undefined,
+                isError: false
+            };
+            // Send the message to the results pane
+            this.eventEmitter.emit('message', message);
+        }
+    }
+
     /**
      * Sets a selection range in the editor for this query
      * @param selection The selection range to select

src/models/utils.ts

@@ -310,11 +310,17 @@ export function parseTimeString(value: string): number | boolean {
     }
     let tempVal = value.split('.');
 
-    if (tempVal.length !== 2) {
+    if (tempVal.length === 1) {
+        // Ideally would handle more cleanly than this but for now handle case where ms not set
+        tempVal = [tempVal[0], '0'];
+    } else if (tempVal.length !== 2) {
         return false;
     }
 
-    let ms = parseInt(tempVal[1].substring(0, 3), 10);
+    let msString = tempVal[1];
+    let msStringEnd = msString.length < 3 ? msString.length : 3;
+    let ms = parseInt(tempVal[1].substring(0, msStringEnd), 10);
+
     tempVal = tempVal[0].split(':');
 
     if (tempVal.length !== 3) {

test/queryRunner.test.ts

@@ -4,6 +4,7 @@ import { EventEmitter } from 'events';
 import QueryRunner from './../src/controllers/queryRunner';
 import { QueryNotificationHandler } from './../src/controllers/queryNotificationHandler';
 import { SqlOutputContentProvider } from './../src/models/sqlOutputContentProvider';
+import * as Utils from './../src/models/utils';
 import SqlToolsServerClient from './../src/languageservice/serviceclient';
 import {
     QueryExecuteParams,
@@ -185,14 +186,21 @@ suite('Query Runner tests', () => {
         mockEventEmitter.verify(x => x.emit('batchStart', TypeMoq.It.isAny()), TypeMoq.Times.once());
     });
 
-    test('Notification - Batch Complete', () => {
+    function testBatchCompleteNotification(sendBatchTime: boolean): void {
         // Setup: Create a batch completion result
+        let configResult: {[key: string]: any} = {};
+        configResult[Constants.configShowBatchTime] = sendBatchTime;
+        setupWorkspaceConfig(configResult);
+
+        let dateNow = new Date();
+        let fiveSecondsAgo = new Date(dateNow.getTime() - 5000);
+        let elapsedTimeString =  Utils.parseNumAsTimeString(5000);
         let batchComplete: QueryExecuteBatchNotificationParams = {
             ownerUri: 'uri',
             batchSummary: {
-                executionElapsed: undefined,
-                executionEnd: new Date().toISOString(),
-                executionStart: new Date().toISOString(),
+                executionElapsed: elapsedTimeString,
+                executionEnd: dateNow.toISOString(),
+                executionStart: fiveSecondsAgo.toISOString(),
                 hasError: false,
                 id: 0,
                 selection: {startLine: 0, endLine: 0, startColumn: 3, endColumn: 3},
@@ -220,13 +228,14 @@ suite('Query Runner tests', () => {
         };
         let mockEventEmitter = TypeMoq.Mock.ofType(EventEmitter, TypeMoq.MockBehavior.Strict);
         mockEventEmitter.setup(x => x.emit('batchComplete', TypeMoq.It.isAny()));
+        mockEventEmitter.setup(x => x.emit('message', TypeMoq.It.isAny()));
         queryRunner.eventEmitter = mockEventEmitter.object;
         queryRunner.handleBatchComplete(batchComplete);
 
         // Then: It should the remainder of the information and emit a batch complete notification
         assert.equal(queryRunner.batchSets.length, 1);
         let storedBatch = queryRunner.batchSets[0];
-        assert.equal(storedBatch.executionElapsed, undefined);
+        assert.equal(storedBatch.executionElapsed, elapsedTimeString);
         assert.equal(typeof(storedBatch.executionEnd), typeof(batchComplete.batchSummary.executionEnd));
         assert.equal(typeof(storedBatch.executionStart), typeof(batchComplete.batchSummary.executionStart));
         assert.equal(storedBatch.hasError, batchComplete.batchSummary.hasError);
@@ -236,6 +245,17 @@ suite('Query Runner tests', () => {
         assert.equal(storedBatch.resultSetSummaries.length, 0);
 
         mockEventEmitter.verify(x => x.emit('batchComplete', TypeMoq.It.isAny()), TypeMoq.Times.once());
+        let expectedMessageTimes = sendBatchTime ? TypeMoq.Times.once() : TypeMoq.Times.never();
+        mockEventEmitter.verify(x => x.emit('message', TypeMoq.It.isAny()), expectedMessageTimes);
+
+    }
+
+    test('Notification - Batch Complete no message', () => {
+        testBatchCompleteNotification(false);
+    });
+
+    test('Notification - Batch Complete with message', () => {
+        testBatchCompleteNotification(true);
     });
 
     test('Notification - ResultSet Complete w/no previous results', () => {

test/utils.test.ts

@@ -11,7 +11,6 @@ suite('Utility Tests - parseTimeString', () => {
 
     test('should return false if input does not have only 1 period', () => {
         expect(Utils.parseTimeString('32:13:23.12.1')).to.equal(false);
-        expect(Utils.parseTimeString('12:32:33')).to.equal(false);
     });
 
     test('should return false if input does not have 2 :', () => {
@@ -23,6 +22,8 @@ suite('Utility Tests - parseTimeString', () => {
         expect(Utils.parseTimeString('2:13:30.0')).to.equal(8010000);
         expect(Utils.parseTimeString('0:0:0.220')).to.equal(220);
         expect(Utils.parseTimeString('0:0:0.0')).to.equal(0);
+        // Allow time without milliseconds
+        expect(Utils.parseTimeString('2:13:30')).to.equal(8010000);
     });
 });