Skip to content

Commit

Permalink
test: concurrency tests in configFile
Browse files Browse the repository at this point in the history
  • Loading branch information
mshanemc committed Oct 25, 2023
1 parent d2e31b4 commit ead7330
Show file tree
Hide file tree
Showing 5 changed files with 252 additions and 33 deletions.
18 changes: 14 additions & 4 deletions src/config/configFile.ts
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@
import * as fs from 'fs';
import { constants as fsConstants, Stats as fsStats } from 'fs';
import { homedir as osHomedir } from 'os';
import { dirname as pathDirname, join as pathJoin } from 'path';
import { basename, dirname as pathDirname, join as pathJoin } from 'path';
import { lock, lockSync } from 'proper-lockfile';
import { parseJsonMap } from '@salesforce/kit';
import { Global } from '../global';
Expand Down Expand Up @@ -179,7 +179,7 @@ export class ConfigFile<
this.hasRead = true;
if ((err as SfError).code === 'ENOENT') {
if (!throwOnNotFound) {
this.setContentsFromFileContents({} as P, process.hrtime.bigint());
this.setContentsFromFileContents({} as P);
return this.getContents();
}
}
Expand Down Expand Up @@ -215,7 +215,7 @@ export class ConfigFile<
this.hasRead = true;
if ((err as SfError).code === 'ENOENT') {
if (!throwOnNotFound) {
this.setContentsFromFileContents({} as P, process.hrtime.bigint());
this.setContentsFromFileContents({} as P);
return this.getContents();
}
}
Expand Down Expand Up @@ -244,7 +244,16 @@ export class ConfigFile<
let unlockFn: (() => Promise<void>) | undefined;
// lock the file. Returns an unlock function to call when done.
try {
unlockFn = await lock(this.getPath(), lockRetryOptions);
if (await this.exists()) {
unlockFn = await lock(this.getPath(), lockRetryOptions);
} else {
// lock the entire directory to keep others from trying to create the file while we are
unlockFn = await lock(basename(this.getPath()), lockRetryOptions);
this.logger.debug(
`No file found at ${this.getPath()}. Write will create it. Locking the entire directory until file is written.`
);
}

// get the file modstamp. Do this after the lock acquisition in case the file is being written to.
const fileTimestamp = (await fs.promises.stat(this.getPath(), { bigint: true })).mtimeNs;

Expand All @@ -253,6 +262,7 @@ export class ConfigFile<
parseJsonMap<P>(await fs.promises.readFile(this.getPath(), 'utf8'), this.getPath()),
fileTimestamp
);

// merge the new contents into the in-memory LWWMap
this.contents.merge(stateFromFile);
} catch (err) {
Expand Down
28 changes: 19 additions & 9 deletions src/config/lwwMap.ts
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
*/

import { entriesOf } from '@salesforce/ts-types';
import { nowBigInt } from '../util/time';
import { LWWRegister } from './lwwRegister';
import { ConfigContents, Key } from './configStackTypes';

Expand All @@ -19,15 +20,18 @@ export type LWWState<P> = {
* @param contents object aligning with ConfigContents
* @param timestamp a bigInt that sets the timestamp. Defaults to the current time
* construct a LWWState from an object
*
* @param keysToCheckForDeletion if a key is in this array, AND not in the contents, it will be marked as deleted
* */
export const stateFromContents = <P extends ConfigContents>(
contents: P,
timestamp = process.hrtime.bigint()
): LWWState<P> =>
export const stateFromContents = <P extends ConfigContents>(contents: P, timestamp?: bigint): LWWState<P> =>
Object.fromEntries(
entriesOf(contents).map(([key, value]) => [key, new LWWRegister({ timestamp, value })])
) as unknown as LWWState<P>;
entriesOf(contents).map(
([key, value]): [keyof P, LWWRegister<P[typeof key] | typeof SYMBOL_FOR_DELETED>['state']] => [
key,
new LWWRegister<typeof value>({ timestamp: timestamp ?? nowBigInt(), value }),
]
)
// I'd love to get rid of this ASsertion but don't know how.
) as LWWState<P>;

export class LWWMap<P extends ConfigContents> {
/** map of key to LWWRegister. Used for managing conflicts */
Expand Down Expand Up @@ -56,7 +60,10 @@ export class LWWMap<P extends ConfigContents> {
) as LWWState<P>;
}

// Merge top-level properties of the incoming state with the current state.
// The value with the latest timestamp wins.
public merge(state: LWWState<P>): LWWState<P> {
// properties that are in the incoming state but not the current state might have been deleted.
// recursively merge each key's register with the incoming state for that key
for (const [key, remote] of entriesOf(state)) {
const local = this.#data.get(key);
Expand All @@ -75,7 +82,7 @@ export class LWWMap<P extends ConfigContents> {
// if the register already exists, set the value
if (register) register.set(value);
// otherwise, instantiate a new `LWWRegister` with the value
else this.#data.set(key, new LWWRegister({ timestamp: process.hrtime.bigint(), value }));
else this.#data.set(key, new LWWRegister({ timestamp: nowBigInt(), value }));
}

public get<K extends Key<P>>(key: K): P[K] | undefined {
Expand All @@ -88,7 +95,10 @@ export class LWWMap<P extends ConfigContents> {
public delete<K extends Key<P>>(key: K): void {
this.#data.set(
key,
new LWWRegister<typeof SYMBOL_FOR_DELETED>({ timestamp: process.hrtime.bigint(), value: SYMBOL_FOR_DELETED })
new LWWRegister<typeof SYMBOL_FOR_DELETED>({
timestamp: nowBigInt(),
value: SYMBOL_FOR_DELETED,
})
);
}

Expand Down
193 changes: 193 additions & 0 deletions test/unit/config/configFileConcurrency.test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,193 @@
/*
* Copyright (c) 2023, salesforce.com, inc.
* All rights reserved.
* Licensed under the BSD 3-Clause license.
* For full license text, see LICENSE.txt file in the repo root or https://opensource.org/licenses/BSD-3-Clause
*/
import { join } from 'node:path';
import { tmpdir } from 'node:os';
import { rm } from 'node:fs/promises';
import { expect } from 'chai';
import { sleep } from '@salesforce/kit';
import { ConfigFile } from '../../../src/exported';

const FILENAME = 'concurrency.json';
const sharedLocation = join('sfdx-core-ut', 'test', 'configFile');

class TestConfig extends ConfigFile<ConfigFile.Options> {
public static getOptions(
filename: string,
isGlobal: boolean,
isState?: boolean,
filePath?: string
): ConfigFile.Options {
return {
rootFolder: tmpdir(),
filename,
isGlobal,
isState,
filePath,
};
}

public static getFileName() {
return FILENAME;
}
}

/* file and node - clock timestamps aren't precise enough to run in a UT.
* the goal of this and the `sleep` is to put a bit of space between operations
* to simulate real-world concurrency where it's unlikely to hit the same ms
*/
const SLEEP_FUDGE_MS = 5;

describe('concurrency', () => {
beforeEach(async () => {
await rm(join(tmpdir(), '.sfdx', 'sfdx-core-ut'), { recursive: true, force: true });
});
afterEach(async () => {
await rm(join(tmpdir(), '.sfdx', 'sfdx-core-ut'), { recursive: true, force: true });
});

it('merges in new props from file saved since a prop was set in memory', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);
const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config2.set('x', 1);
await config2.write();

const c1output = await config1.write();
expect(c1output.x).to.equal(1);
});

it('newer props beat older files', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));

const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config2.set('x', 1);
await config2.write();
await sleep(SLEEP_FUDGE_MS);

config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);

const c1output = await config1.write();
expect(c1output.x).to.equal(0);
});

it('"deleted" (missing) props in a file do not delete from contents"', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);

const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config2.set('x', 1);
config2.unset('x');
await sleep(SLEEP_FUDGE_MS);

await config2.write();
await sleep(SLEEP_FUDGE_MS);

const c1output = await config1.write();
expect(c1output.x).to.equal(0);
});

it('newer deleted props beat older files', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);

const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config2.set('x', 1);

await config2.write();
await sleep(SLEEP_FUDGE_MS);

config1.unset('x');

const c1output = await config1.write();
expect(c1output.x).to.equal(undefined);
});

it('deleted in both memory and file', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);

const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
config2.set('x', 1);

await config2.write();
await sleep(SLEEP_FUDGE_MS);

config2.unset('x');
await config2.write();

await sleep(SLEEP_FUDGE_MS);
config1.unset('x');

const c1output = await config1.write();
expect(c1output.x).to.equal(undefined);
});

it('parallel writes from different processes produce valid json when file exists', async () => {
const config1 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
await config1.write();
const config2 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
const config3 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));
const config4 = new TestConfig(TestConfig.getOptions(FILENAME, true, true, sharedLocation));

config1.set('x', 0);
await sleep(SLEEP_FUDGE_MS);
config2.set('x', 1);
config2.set('b', 2);
await sleep(SLEEP_FUDGE_MS);
config3.set('x', 2);
config3.set('c', 3);
await sleep(SLEEP_FUDGE_MS);
config4.set('x', 3);
await sleep(SLEEP_FUDGE_MS);

// simulate non-deterministic parallel operations from different processes. We can't guarantee the order of files,
// so this might result in a set prop being deleted.
await Promise.all([config1.write(), config2.write(), config3.write(), config4.write()]);
await Promise.all([config1.read(), config2.read(), config3.read(), config4.read()]);
// timestamps on the files are treated as the stamp for all props,
// since we lose the CRDT prop - level timestamps when writing to json
expect(config1.get('x')).to.be.greaterThanOrEqual(0).and.lessThanOrEqual(3);
if (config1.has('b')) {
expect(config1.get('b')).to.equal(2);
}
if (config1.has('c')) {
expect(config1.get('c')).to.equal(3);
}
if (config2.has('b')) {
expect(config2.get('b')).to.equal(2);
}
if (config2.has('c')) {
expect(config2.get('c')).to.equal(3);
}
});

it('parallel writes, reverse order, with deletes', async () => {
const config1 = new TestConfig(TestConfig.getOptions('test', true, true, sharedLocation));
const config2 = new TestConfig(TestConfig.getOptions('test', true, true, sharedLocation));
const config3 = new TestConfig(TestConfig.getOptions('test', true, true, sharedLocation));
const config4 = new TestConfig(TestConfig.getOptions('test', true, true, sharedLocation));

config1.set('x', 7);
await sleep(SLEEP_FUDGE_MS);
config2.set('x', 8);
await sleep(SLEEP_FUDGE_MS);
config3.set('x', 9);
await sleep(SLEEP_FUDGE_MS);
config4.unset('x');

await Promise.all([config4.write(), config3.write(), config2.write(), config1.write()]);
await Promise.all([config1.read(), config2.read(), config3.read(), config4.read()]);
if (config4.has('x')) {
expect(config4.get('x')).to.be.greaterThanOrEqual(7).and.lessThanOrEqual(9);
}
});
});
43 changes: 25 additions & 18 deletions test/unit/config/lwwMapTest.ts
Original file line number Diff line number Diff line change
Expand Up @@ -9,18 +9,21 @@ import { LWWMap, LWWState, SYMBOL_FOR_DELETED } from '../../../src/config/lwwMap
import { nowBigInt } from '../../../src/util/time';

config.truncateThreshold = 0;
const TIMESTAMP_OFFSET = BigInt(1_000_000);
// unit is ns. 1_000_000_000 ns = 1s
const TIMESTAMP_OFFSET = BigInt(1_000_000_000);

describe('LWWMap', () => {
type TestType = { foo: string; baz: string; opt?: number; optNull?: null };
let state: LWWState<TestType>;

describe('all properties are known', () => {
const state = {
foo: { value: 'bar', timestamp: nowBigInt() },
baz: { value: 'qux', timestamp: nowBigInt() },
};
let lwwMap: LWWMap<TestType>;

beforeEach(() => {
state = {
foo: { value: 'bar', timestamp: nowBigInt() },
baz: { value: 'qux', timestamp: nowBigInt() },
};
lwwMap = new LWWMap(state);
});

Expand Down Expand Up @@ -154,24 +157,28 @@ describe('LWWMap', () => {
expect(lwwMap.state.gone.value).to.equal(SYMBOL_FOR_DELETED);
});
});
describe('nested objects', () => {
const state = {
});

describe('nested objects', () => {
type NestedOpenEndedObject = { foo: string; baz: string; opt?: number; optNull?: null; obj: Record<string, number> };

let state: LWWState<NestedOpenEndedObject>;
let lwwMap: LWWMap<NestedOpenEndedObject>;

beforeEach(() => {
state = {
foo: { value: 'bar', timestamp: nowBigInt() },
baz: { value: 'qux', timestamp: nowBigInt() },
obj: { value: { a: 1, b: 2, c: 3 }, timestamp: nowBigInt() },
};
let lwwMap: LWWMap<{ foo: string; baz: string; opt?: number; optNull?: null }>;

beforeEach(() => {
lwwMap = new LWWMap(state);
});
lwwMap = new LWWMap(state);
});

it('should initialize with the correct state', () => {
expect(lwwMap.state).to.deep.equal(state);
});
it('should initialize with the correct state', () => {
expect(lwwMap.state).to.deep.equal(state);
});

it('should get the correct value for the entire object', () => {
expect(lwwMap.value).to.deep.equal({ foo: 'bar', baz: 'qux', obj: { a: 1, b: 2, c: 3 } });
});
it('should get the correct value for the entire object', () => {
expect(lwwMap.value).to.deep.equal({ foo: 'bar', baz: 'qux', obj: { a: 1, b: 2, c: 3 } });
});
});
3 changes: 1 addition & 2 deletions test/unit/org/orgTest.ts
Original file line number Diff line number Diff line change
Expand Up @@ -640,9 +640,8 @@ describe('Org Tests', () => {
expect(info).has.property('value', org0Username);

const org1Username = orgs[1].getUsername();

assert(org1Username);
const stateAggregator = await StateAggregator.getInstance();
// @ts-expect-error: user is nullable
stateAggregator.aliases.set('foo', org1Username);
const user = stateAggregator.aliases.getUsername('foo');
expect(user).eq(org1Username);
Expand Down

3 comments on commit ead7330

@svc-cli-bot
Copy link
Contributor

Choose a reason for hiding this comment

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

Logger Benchmarks - ubuntu-latest

Benchmark suite Current: ead7330 Previous: 02bc9d6 Ratio
Child logger creation 432600 ops/sec (±9.99%) 473126 ops/sec (±8.65%) 1.09
Logging a string on root logger 524492 ops/sec (±10.11%) 637687 ops/sec (±11.36%) 1.22
Logging an object on root logger 324483 ops/sec (±17.10%) 378667 ops/sec (±16.24%) 1.17
Logging an object with a message on root logger 281653 ops/sec (±11.80%) 214855 ops/sec (±18.32%) 0.76
Logging an object with a redacted prop on root logger 274962 ops/sec (±15.67%) 258952 ops/sec (±17.47%) 0.94
Logging a nested 3-level object on root logger 2222 ops/sec (±220.42%) 11460 ops/sec (±187.02%) 5.16

This comment was automatically generated by workflow using github-action-benchmark.

@svc-cli-bot
Copy link
Contributor

Choose a reason for hiding this comment

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

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'Logger Benchmarks - ubuntu-latest'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 2.

Benchmark suite Current: ead7330 Previous: 02bc9d6 Ratio
Logging a nested 3-level object on root logger 2222 ops/sec (±220.42%) 11460 ops/sec (±187.02%) 5.16

This comment was automatically generated by workflow using github-action-benchmark.

@svc-cli-bot
Copy link
Contributor

Choose a reason for hiding this comment

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

Logger Benchmarks - windows-latest

Benchmark suite Current: ead7330 Previous: 02bc9d6 Ratio
Child logger creation 342127 ops/sec (±7.26%) 391874 ops/sec (±1.33%) 1.15
Logging a string on root logger 441560 ops/sec (±14.38%) 461299 ops/sec (±10.27%) 1.04
Logging an object on root logger 256861 ops/sec (±26.20%) 285973 ops/sec (±20.41%) 1.11
Logging an object with a message on root logger 168638 ops/sec (±17.86%) 167689 ops/sec (±17.87%) 0.99
Logging an object with a redacted prop on root logger 177038 ops/sec (±24.65%) 165913 ops/sec (±21.87%) 0.94
Logging a nested 3-level object on root logger 120811 ops/sec (±23.64%) 117310 ops/sec (±24.53%) 0.97

This comment was automatically generated by workflow using github-action-benchmark.

Please sign in to comment.