Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Compute timestamp Using Date.now (without deriving from duration) #1431

Merged
merged 3 commits into from
Sep 11, 2020
Merged

Compute timestamp Using Date.now (without deriving from duration) #1431

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
1d5aa55
Compute timestamp Using Date.now (without deriving from duration)
Sep 9, 2020
7c1a52e
Calculate test run duration from testRunStarted and testRunFinished t…
cbliard Sep 10, 2020
6109441
Move dubious code to test code
Sep 10, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 7 additions & 13 deletions src/formatter/helpers/summary_helpers.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,14 +1,10 @@
import _ from 'lodash'
import Duration from 'duration'
import Status from '../../status'
import {
addDurations,
durationToMilliseconds,
getZeroDuration,
} from '../../time'
import { addDurations, getZeroDuration } from '../../time'
import { IColorFns } from '../get_color_fns'
import { ITestCaseAttempt } from './event_data_collector'
import { messages } from '@cucumber/messages'
import { messages, TimeConversion } from '@cucumber/messages'

const STATUS_REPORT_ORDER = [
Status.FAILED,
Expand All @@ -22,13 +18,13 @@ const STATUS_REPORT_ORDER = [
export interface IFormatSummaryRequest {
colorFns: IColorFns
testCaseAttempts: ITestCaseAttempt[]
testRunFinished: messages.ITestRunFinished
testRunDuration: messages.IDuration
}

export function formatSummary({
colorFns,
testCaseAttempts,
testRunFinished,
testRunDuration,
}: IFormatSummaryRequest): string {
const testCaseResults: messages.TestStepFinished.ITestStepResult[] = []
const testStepResults: messages.TestStepFinished.ITestStepResult[] = []
Expand Down Expand Up @@ -57,7 +53,7 @@ export function formatSummary({
type: 'step',
})
const durationSummary = `${getDurationSummary(
testRunFinished.timestamp
testRunDuration
)} (executing steps: ${getDurationSummary(totalStepDuration)})\n`
return [scenarioSummary, stepSummary, durationSummary].join('\n')
}
Expand Down Expand Up @@ -92,11 +88,9 @@ function getCountSummary({
return text
}

function getDurationSummary(
durationMsg: messages.IDuration | messages.ITimestamp
): string {
function getDurationSummary(durationMsg: messages.IDuration): string {
const start = new Date(0)
const end = new Date(durationToMilliseconds(durationMsg))
const end = new Date(TimeConversion.durationToMilliseconds(durationMsg))
const duration = new Duration(start, end)
// Use spaces in toString method for readability and to avoid %Ls which is a format
return duration.toString('%Ms m %S . %L s').replace(/ /g, '')
Expand Down
25 changes: 22 additions & 3 deletions src/formatter/helpers/summary_helpers_spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@ import { formatSummary } from './summary_helpers'
import { getTestCaseAttempts } from '../../../test/formatter_helpers'
import { getBaseSupportCodeLibrary } from '../../../test/fixtures/steps'
import FakeTimers, { InstalledClock } from '@sinonjs/fake-timers'
import timeMethods from '../../time'
import timeMethods, { durationBetweenTimestamps } from '../../time'
import { buildSupportCodeLibrary } from '../../../test/runtime_helpers'
import { IRuntimeOptions } from '../../runtime'
import { ISupportCodeLibrary } from '../../support_code_library_builder/types'
Expand All @@ -16,13 +16,15 @@ interface ITestFormatSummaryOptions {
runtimeOptions?: Partial<IRuntimeOptions>
sourceData: string
supportCodeLibrary?: ISupportCodeLibrary
testRunStarted?: messages.ITestRunStarted
testRunFinished?: messages.ITestRunFinished
}

async function testFormatSummary({
runtimeOptions,
sourceData,
supportCodeLibrary,
testRunStarted,
testRunFinished,
}: ITestFormatSummaryOptions): Promise<string> {
const sources = [
Expand All @@ -34,6 +36,14 @@ async function testFormatSummary({
if (doesNotHaveValue(supportCodeLibrary)) {
supportCodeLibrary = getBaseSupportCodeLibrary()
}
if (doesNotHaveValue(testRunStarted)) {
testRunStarted = messages.TestRunStarted.fromObject({
timestamp: {
nanos: 0,
seconds: 0,
},
})
}
if (doesNotHaveValue(testRunFinished)) {
testRunFinished = messages.TestRunFinished.fromObject({
timestamp: {
Expand All @@ -50,7 +60,10 @@ async function testFormatSummary({
return formatSummary({
colorFns: getColorFns(false),
testCaseAttempts,
testRunFinished,
testRunDuration: durationBetweenTimestamps(
testRunStarted.timestamp,
testRunFinished.timestamp
),
})
}

Expand Down Expand Up @@ -242,10 +255,16 @@ describe('SummaryHelpers', () => {
const output = await testFormatSummary({
sourceData,
supportCodeLibrary,
testRunStarted: messages.TestRunStarted.fromObject({
timestamp: {
nanos: 0,
seconds: 3,
},
}),
testRunFinished: messages.TestRunFinished.fromObject({
timestamp: {
nanos: 124000000,
seconds: 0,
seconds: 3,
},
}),
})
Expand Down
10 changes: 9 additions & 1 deletion src/formatter/progress_bar_formatter.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,10 +5,12 @@ import { WriteStream as TtyWriteStream } from 'tty'
import { messages } from '@cucumber/messages'
import { doesHaveValue, valueOrDefault } from '../value_checker'
import { formatUndefinedParameterType } from './helpers/issue_helpers'
import { durationBetweenTimestamps } from '../time'

// Inspired by https://github.com/thekompanee/fuubar and https://github.com/martinciu/fuubar-cucumber
export default class ProgressBarFormatter extends Formatter {
private numberOfSteps: number
private testRunStarted: messages.ITestRunStarted
private issueCount: number
public progressBar: ProgressBar

Expand Down Expand Up @@ -87,11 +89,15 @@ export default class ProgressBarFormatter extends Formatter {
}

logSummary(testRunFinished: messages.ITestRunFinished): void {
const testRunDuration = durationBetweenTimestamps(
this.testRunStarted.timestamp,
testRunFinished.timestamp
)
this.log(
formatSummary({
colorFns: this.colorFns,
testCaseAttempts: this.eventDataCollector.getTestCaseAttempts(),
testRunFinished,
testRunDuration,
})
)
}
Expand All @@ -107,6 +113,8 @@ export default class ProgressBarFormatter extends Formatter {
this.logProgress(envelope.testStepFinished)
} else if (doesHaveValue(envelope.testCaseFinished)) {
this.logErrorIfNeeded(envelope.testCaseFinished)
} else if (doesHaveValue(envelope.testRunStarted)) {
this.testRunStarted = envelope.testRunStarted
} else if (doesHaveValue(envelope.testRunFinished)) {
this.logSummary(envelope.testRunFinished)
}
Expand Down
17 changes: 14 additions & 3 deletions src/formatter/summary_formatter.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ import { doesHaveValue } from '../value_checker'
import { messages } from '@cucumber/messages'
import { ITestCaseAttempt } from './helpers/event_data_collector'
import { formatUndefinedParameterTypes } from './helpers/issue_helpers'
import { durationBetweenTimestamps } from '../time'

interface ILogIssuesRequest {
issues: ITestCaseAttempt[]
Expand All @@ -14,14 +15,24 @@ interface ILogIssuesRequest {
export default class SummaryFormatter extends Formatter {
constructor(options: IFormatterOptions) {
super(options)
let testRunStartedTimestamp: messages.ITimestamp
options.eventBroadcaster.on('envelope', (envelope: messages.IEnvelope) => {
if (doesHaveValue(envelope.testRunStarted)) {
testRunStartedTimestamp = envelope.testRunStarted.timestamp
}
if (doesHaveValue(envelope.testRunFinished)) {
this.logSummary(envelope.testRunFinished)
const testRunFinishedTimestamp = envelope.testRunFinished.timestamp
this.logSummary(
durationBetweenTimestamps(
testRunStartedTimestamp,
testRunFinishedTimestamp
)
)
}
})
}

logSummary(testRunFinished: messages.ITestRunFinished): void {
logSummary(testRunDuration: messages.IDuration): void {
const failures: ITestCaseAttempt[] = []
const warnings: ITestCaseAttempt[] = []
const testCaseAttempts = this.eventDataCollector.getTestCaseAttempts()
Expand Down Expand Up @@ -49,7 +60,7 @@ export default class SummaryFormatter extends Formatter {
formatSummary({
colorFns: this.colorFns,
testCaseAttempts,
testRunFinished,
testRunDuration,
})
)
}
Expand Down
5 changes: 1 addition & 4 deletions src/runtime/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -129,10 +129,7 @@ export default class Runtime {
'envelope',
new messages.Envelope({
testRunStarted: {
timestamp: {
nanos: 0,
seconds: 0,
},
timestamp: this.stopwatch.timestamp(),
},
})
)
Expand Down
5 changes: 1 addition & 4 deletions src/runtime/parallel/coordinator.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -205,10 +205,7 @@ export default class Coordinator {
'envelope',
new messages.Envelope({
testRunStarted: {
timestamp: {
nanos: 0,
seconds: 0,
},
timestamp: this.stopwatch.timestamp(),
},
})
)
Expand Down
24 changes: 12 additions & 12 deletions src/runtime/pickle_runner_spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,28 +125,28 @@ describe('PickleRunner', () => {
attempt: 0,
id: '2',
testCaseId: '0',
timestamp: predictableTimestamp(1),
timestamp: predictableTimestamp(0),
},
}),
messages.Envelope.fromObject({
testStepStarted: {
testCaseStartedId: '2',
testStepId: '1',
timestamp: predictableTimestamp(2),
timestamp: predictableTimestamp(1),
},
}),
messages.Envelope.fromObject({
testStepFinished: {
testCaseStartedId: '2',
testStepResult: passedTestResult,
testStepId: '1',
timestamp: predictableTimestamp(3),
timestamp: predictableTimestamp(2),
},
}),
messages.Envelope.fromObject({
testCaseFinished: {
testCaseStartedId: '2',
timestamp: predictableTimestamp(4),
timestamp: predictableTimestamp(3),
},
}),
])
Expand Down Expand Up @@ -401,14 +401,14 @@ describe('PickleRunner', () => {
attempt: 0,
id: '2',
testCaseId: '0',
timestamp: predictableTimestamp(1),
timestamp: predictableTimestamp(0),
},
}),
messages.Envelope.fromObject({
testStepStarted: {
testCaseStartedId: '2',
testStepId: '1',
timestamp: predictableTimestamp(2),
timestamp: predictableTimestamp(1),
},
}),
messages.Envelope.fromObject({
Expand All @@ -421,28 +421,28 @@ describe('PickleRunner', () => {
willBeRetried: true,
},
testStepId: '1',
timestamp: predictableTimestamp(3),
timestamp: predictableTimestamp(2),
},
}),
messages.Envelope.fromObject({
testCaseFinished: {
testCaseStartedId: '2',
timestamp: predictableTimestamp(4),
timestamp: predictableTimestamp(3),
},
}),
messages.Envelope.fromObject({
testCaseStarted: {
attempt: 1,
id: '3',
testCaseId: '0',
timestamp: predictableTimestamp(5),
timestamp: predictableTimestamp(4),
},
}),
messages.Envelope.fromObject({
testStepStarted: {
testCaseStartedId: '3',
testStepId: '1',
timestamp: predictableTimestamp(6),
timestamp: predictableTimestamp(5),
},
}),
messages.Envelope.fromObject({
Expand All @@ -453,13 +453,13 @@ describe('PickleRunner', () => {
status: Status.PASSED,
},
testStepId: '1',
timestamp: predictableTimestamp(7),
timestamp: predictableTimestamp(6),
},
}),
messages.Envelope.fromObject({
testCaseFinished: {
testCaseStartedId: '3',
timestamp: predictableTimestamp(8),
timestamp: predictableTimestamp(7),
},
}),
])
Expand Down
22 changes: 12 additions & 10 deletions src/runtime/stopwatch.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import { messages } from '@cucumber/messages'
import { messages, TimeConversion } from '@cucumber/messages'
import { stopwatch, Stopwatch, duration, Duration } from 'durations'

export interface ITestRunStopwatch {
Expand Down Expand Up @@ -37,7 +37,7 @@ export class RealTestRunStopwatch implements ITestRunStopwatch {
}

timestamp(): messages.ITimestamp {
return convertToTimestamp(this.duration())
return TimeConversion.millisecondsSinceEpochToTimestamp(Date.now())
}
}

Expand Down Expand Up @@ -67,16 +67,18 @@ export class PredictableTestRunStopwatch implements ITestRunStopwatch {
}

timestamp(): messages.ITimestamp {
const fakeTimestamp = this.convertToTimestamp(this.duration())
this.count++
return convertToTimestamp(this.duration())
return fakeTimestamp
}
}

function convertToTimestamp(duration: Duration): messages.ITimestamp {
const seconds = Math.floor(duration.seconds())
const nanos = Math.floor((duration.seconds() - seconds) * 1000000000)
return {
seconds,
nanos,
// TODO: Remove. It's impossible to convert timestamps to durations and vice-versa
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is preventing us from doing this now?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nothing in particular - just didn't want to go down the rabbit hole. My thinking is that we need a more thorough review/overhaul of how we handle wall time vs monotonic time in a separate PR, and this can be addressed then.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay yeah, so the stopwatch concept I guess becomes unnecessary and we should probably be able to infer any durations we want by finding the started/finished messages and using their timestamps.

(I'm happy to pick that up BTW since this is borne of my mistake.)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should use monotonic timestamps to calculate duration values and wall time to calculate timestamp values.

In JavaScript, wall time (CLOCK_REALTIME) is used in Date.now(). Monotonic time (CLOCK_MONOTONIC) is used in performance.now() (available on window in browsers and from perf_hooks in Node.js).

What's important to realise is that wall time can go backwards. In other words, Date.now() is unsuitable for durations. It's only suitable for timestamps. On the flip side, performance.now() is the right choice for durations, and the wrong choice for timestamps.

The only reason we're calculating the test run duration with wall time is that I found it difficult to do it with the current stopwatch. Now that I think of it, it's probably not that hard.

I think all of this will be easier if we drop the duration and durations modules and implement our own. It's also a good way to understand how to implement a stopwatch and a clock.

I propose the following API for a (wall) clock:

type Timestamp = number
type Clock = () => Timestamp

const clock: Clock = ...
const timestamp = clock()

And a stop watch:

type Duration = number
type StartStopwatch = () => StopStopwatch
type StopStopwatch = () => Duration

const startStopwatch: StartStopwatch = ...
const stopStopwatch = startStopWatch()
doSomeWork()
const duration = stopStopwatch()

I started this in #1430 but I abandoned it in favour of this PR because I went too far down a rabbit hole. I'd like to give it another try though. Or maybe you want to have a stab at it @davidjgoss?

private convertToTimestamp(duration: Duration): messages.ITimestamp {
const seconds = Math.floor(duration.seconds())
const nanos = Math.floor((duration.seconds() - seconds) * 1000000000)
return {
seconds,
nanos,
}
}
}
Loading