Skip to content

Commit e2b30fe

Browse files
zashraf1985zashraf1985
authored
Logging performance improvements (#713)
## Summary Made improvements to logging performance. Log messages were previously being concatenated even if log level didn't apply. modified it to do the concatenation only when log level applies. this improves SDK performance specially in case of log level `ERROR`. ## Test plan - All existing tests pass
1 parent d4ff5bd commit e2b30fe

16 files changed

Lines changed: 1170 additions & 1041 deletions

File tree

‎packages/optimizely-sdk/lib/core/audience_evaluator/index.tests.js‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -16,11 +16,13 @@
1616
import sinon from 'sinon';
1717
import { assert } from 'chai';
1818
import { getLogger } from '@optimizely/js-sdk-logging';
19+
import { sprintf } from '@optimizely/js-sdk-utils';
1920

2021
import { createAudienceEvaluator } from './index';
2122
import * as conditionTreeEvaluator from '../condition_tree_evaluator';
2223
import * as customAttributeConditionEvaluator from '../custom_attribute_condition_evaluator';
2324

25+
var buildLogMessageFromArgs = args => sprintf(args[1], ...args.splice(2));
2426
var mockLogger = getLogger();
2527

2628
var chromeUserAudience = {
@@ -233,10 +235,10 @@ describe('lib/core/audience_evaluator', function() {
233235
assert.isFalse(result);
234236
assert.strictEqual(2, mockLogger.log.callCount);
235237
assert.strictEqual(
236-
mockLogger.log.args[0][1],
238+
buildLogMessageFromArgs(mockLogger.log.args[0]),
237239
'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
238240
);
239-
assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to UNKNOWN.');
241+
assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to UNKNOWN.');
240242
});
241243

242244
it('logs correctly when conditionTreeEvaluator.evaluate returns true', function() {
@@ -255,10 +257,10 @@ describe('lib/core/audience_evaluator', function() {
255257
assert.isTrue(result);
256258
assert.strictEqual(2, mockLogger.log.callCount);
257259
assert.strictEqual(
258-
mockLogger.log.args[0][1],
260+
buildLogMessageFromArgs(mockLogger.log.args[0]),
259261
'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
260262
);
261-
assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to TRUE.');
263+
assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to TRUE.');
262264
});
263265

264266
it('logs correctly when conditionTreeEvaluator.evaluate returns false', function() {
@@ -277,10 +279,10 @@ describe('lib/core/audience_evaluator', function() {
277279
assert.isFalse(result);
278280
assert.strictEqual(2, mockLogger.log.callCount);
279281
assert.strictEqual(
280-
mockLogger.log.args[0][1],
282+
buildLogMessageFromArgs(mockLogger.log.args[0]),
281283
'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
282284
);
283-
assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to FALSE.');
285+
assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to FALSE.');
284286
});
285287
});
286288
});

‎packages/optimizely-sdk/lib/core/audience_evaluator/index.ts‎

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,6 @@
1313
* See the License for the specific language governing permissions and
1414
* limitations under the License.
1515
*/
16-
import { sprintf } from '@optimizely/js-sdk-utils';
1716
import { getLogger } from '@optimizely/js-sdk-logging';
1817

1918
import fns from '../../utils/fns';
@@ -77,14 +76,14 @@ export class AudienceEvaluator {
7776
if (audience) {
7877
logger.log(
7978
LOG_LEVEL.DEBUG,
80-
sprintf(LOG_MESSAGES.EVALUATING_AUDIENCE, MODULE_NAME, audienceId, JSON.stringify(audience.conditions))
79+
LOG_MESSAGES.EVALUATING_AUDIENCE, MODULE_NAME, audienceId, JSON.stringify(audience.conditions)
8180
);
8281
const result = conditionTreeEvaluator.evaluate(
8382
audience.conditions as unknown[] ,
8483
this.evaluateConditionWithUserAttributes.bind(this, userAttributes)
8584
);
8685
const resultText = result === null ? 'UNKNOWN' : result.toString().toUpperCase();
87-
logger.log(LOG_LEVEL.DEBUG, sprintf(LOG_MESSAGES.AUDIENCE_EVALUATION_RESULT, MODULE_NAME, audienceId, resultText));
86+
logger.log(LOG_LEVEL.DEBUG, LOG_MESSAGES.AUDIENCE_EVALUATION_RESULT, MODULE_NAME, audienceId, resultText);
8887
return result;
8988
}
9089
return null;
@@ -103,15 +102,15 @@ export class AudienceEvaluator {
103102
evaluateConditionWithUserAttributes(userAttributes: UserAttributes, condition: Condition): boolean | null {
104103
const evaluator = this.typeToEvaluatorMap[condition.type];
105104
if (!evaluator) {
106-
logger.log(LOG_LEVEL.WARNING, sprintf(LOG_MESSAGES.UNKNOWN_CONDITION_TYPE, MODULE_NAME, JSON.stringify(condition)));
105+
logger.log(LOG_LEVEL.WARNING, LOG_MESSAGES.UNKNOWN_CONDITION_TYPE, MODULE_NAME, JSON.stringify(condition));
107106
return null;
108107
}
109108
try {
110109
return evaluator.evaluate(condition, userAttributes);
111110
} catch (err) {
112111
logger.log(
113112
LOG_LEVEL.ERROR,
114-
sprintf(ERROR_MESSAGES.CONDITION_EVALUATOR_ERROR, MODULE_NAME, condition.type, err.message)
113+
ERROR_MESSAGES.CONDITION_EVALUATOR_ERROR, MODULE_NAME, condition.type, err.message
115114
);
116115
}
117116

‎packages/optimizely-sdk/lib/core/bucketer/index.tests.js‎

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@ import { createLogger } from '../../plugins/logger';
2828
import projectConfig from '../project_config';
2929
import { getTestProjectConfig } from '../../tests/test_data';
3030

31+
var buildLogMessageFromArgs = args => sprintf(args[1], ...args.splice(2));
3132
var testData = getTestProjectConfig();
3233

3334
describe('lib/core/bucketer', function() {
@@ -75,7 +76,7 @@ describe('lib/core/bucketer', function() {
7576
var decisionResponse = bucketer.bucket(bucketerParamsTest1);
7677
expect(decisionResponse.result).to.equal('111128');
7778

78-
var bucketedUser_log1 = createdLogger.log.args[0][1];
79+
var bucketedUser_log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
7980
expect(bucketedUser_log1).to.equal(
8081
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'ppid1')
8182
);
@@ -84,7 +85,7 @@ describe('lib/core/bucketer', function() {
8485
bucketerParamsTest2.userId = 'ppid2';
8586
expect(bucketer.bucket(bucketerParamsTest2).result).to.equal(null);
8687

87-
var notBucketedUser_log1 = createdLogger.log.args[1][1];
88+
var notBucketedUser_log1 = buildLogMessageFromArgs(createdLogger.log.args[1]);
8889

8990
expect(notBucketedUser_log1).to.equal(
9091
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50000', 'ppid2')
@@ -137,12 +138,12 @@ describe('lib/core/bucketer', function() {
137138
sinon.assert.calledTwice(bucketerStub);
138139
sinon.assert.callCount(createdLogger.log, 3);
139140

140-
var log1 = createdLogger.log.args[0][1];
141+
var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
141142
expect(log1).to.equal(
142143
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'testUser')
143144
);
144145

145-
var log2 = createdLogger.log.args[1][1];
146+
var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
146147
expect(log2).to.equal(
147148
sprintf(
148149
LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
@@ -153,7 +154,7 @@ describe('lib/core/bucketer', function() {
153154
)
154155
);
155156

156-
var log3 = createdLogger.log.args[2][1];
157+
var log3 = buildLogMessageFromArgs(createdLogger.log.args[2]);
157158
expect(log3).to.equal(
158159
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'testUser')
159160
);
@@ -168,11 +169,11 @@ describe('lib/core/bucketer', function() {
168169
sinon.assert.calledOnce(bucketerStub);
169170
sinon.assert.calledTwice(createdLogger.log);
170171

171-
var log1 = createdLogger.log.args[0][1];
172+
var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
172173
expect(log1).to.equal(
173174
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '5000', 'testUser')
174175
);
175-
var log2 = createdLogger.log.args[1][1];
176+
var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
176177
expect(log2).to.equal(
177178
sprintf(
178179
LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
@@ -193,11 +194,11 @@ describe('lib/core/bucketer', function() {
193194
sinon.assert.calledOnce(bucketerStub);
194195
sinon.assert.calledTwice(createdLogger.log);
195196

196-
var log1 = createdLogger.log.args[0][1];
197+
var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
197198
expect(log1).to.equal(
198199
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50000', 'testUser')
199200
);
200-
var log2 = createdLogger.log.args[1][1];
201+
var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
201202
expect(log2).to.equal(sprintf(LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT, 'BUCKETER', 'testUser', '666'));
202203
});
203204

@@ -210,11 +211,11 @@ describe('lib/core/bucketer', function() {
210211
sinon.assert.calledOnce(bucketerStub);
211212
sinon.assert.calledTwice(createdLogger.log);
212213

213-
var log1 = createdLogger.log.args[0][1];
214+
var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
214215
expect(log1).to.equal(
215216
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '9000', 'testUser')
216217
);
217-
var log2 = createdLogger.log.args[1][1];
218+
var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
218219
expect(log2).to.equal(sprintf(LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT, 'BUCKETER', 'testUser', '666'));
219220
});
220221

@@ -252,7 +253,7 @@ describe('lib/core/bucketer', function() {
252253
sinon.assert.calledOnce(bucketerStub);
253254
sinon.assert.calledOnce(createdLogger.log);
254255

255-
var log1 = createdLogger.log.args[0][1];
256+
var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
256257
expect(log1).to.equal(sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '0', 'testUser'));
257258
});
258259

‎packages/optimizely-sdk/lib/core/bucketer/index.ts‎

Lines changed: 51 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,7 @@ const RANDOM_POLICY = 'random';
5656
* null if user is not bucketed into any experiment and the decide reasons.
5757
*/
5858
export const bucket = function(bucketerParams: BucketerParams): DecisionResponse<string | null> {
59-
const decideReasons: string[] = [];
59+
const decideReasons: (string | number)[][] = [];
6060
// Check if user is in a random group; if so, check if user is bucketed into a specific experiment
6161
const experiment = bucketerParams.experimentIdMap[bucketerParams.experimentId];
6262
const groupId = experiment['groupId'];
@@ -75,68 +75,89 @@ export const bucket = function(bucketerParams: BucketerParams): DecisionResponse
7575

7676
// Return if user is not bucketed into any experiment
7777
if (bucketedExperimentId === null) {
78-
const notbucketedInAnyExperimentLogMessage = sprintf(
78+
bucketerParams.logger.log(
79+
LOG_LEVEL.INFO,
7980
LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT,
8081
MODULE_NAME,
8182
bucketerParams.userId,
82-
groupId
83+
groupId,
8384
);
84-
bucketerParams.logger.log(LOG_LEVEL.INFO, notbucketedInAnyExperimentLogMessage);
85-
decideReasons.push(notbucketedInAnyExperimentLogMessage);
85+
decideReasons.push([
86+
LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT,
87+
MODULE_NAME,
88+
bucketerParams.userId,
89+
groupId,
90+
]);
8691
return {
8792
result: null,
8893
reasons: decideReasons,
8994
};
9095
}
9196

9297
// Return if user is bucketed into a different experiment than the one specified
93-
if (bucketedExperimentId !== bucketerParams.experimentId) {
94-
const notBucketedIntoExperimentOfGroupLogMessage = sprintf(
98+
if (bucketedExperimentId !== bucketerParams.experimentId) {
99+
bucketerParams.logger.log(
100+
LOG_LEVEL.INFO,
95101
LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
96102
MODULE_NAME,
97103
bucketerParams.userId,
98104
bucketerParams.experimentKey,
99-
groupId
105+
groupId,
100106
);
101-
bucketerParams.logger.log(LOG_LEVEL.INFO, notBucketedIntoExperimentOfGroupLogMessage);
102-
decideReasons.push(notBucketedIntoExperimentOfGroupLogMessage);
107+
decideReasons.push([
108+
LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
109+
MODULE_NAME,
110+
bucketerParams.userId,
111+
bucketerParams.experimentKey,
112+
groupId,
113+
]);
103114
return {
104115
result: null,
105116
reasons: decideReasons,
106117
};
107118
}
108119

109-
// Continue bucketing if user is bucketed into specified experiment
110-
const bucketedIntoExperimentOfGroupLogMessage = sprintf(
120+
// Continue bucketing if user is bucketed into specified experiment
121+
bucketerParams.logger.log(
122+
LOG_LEVEL.INFO,
111123
LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
112124
MODULE_NAME,
113125
bucketerParams.userId,
114126
bucketerParams.experimentKey,
115-
groupId
127+
groupId,
116128
);
117-
bucketerParams.logger.log(LOG_LEVEL.INFO, bucketedIntoExperimentOfGroupLogMessage);
118-
decideReasons.push(bucketedIntoExperimentOfGroupLogMessage);
129+
decideReasons.push([
130+
LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
131+
MODULE_NAME,
132+
bucketerParams.userId,
133+
bucketerParams.experimentKey,
134+
groupId,
135+
]);
119136
}
120137
}
121-
const bucketingId = sprintf('%s%s', bucketerParams.bucketingId, bucketerParams.experimentId);
138+
const bucketingId = `${bucketerParams.bucketingId}${bucketerParams.experimentId}`;
122139
const bucketValue = _generateBucketValue(bucketingId);
123-
124-
const bucketedUserLogMessage = sprintf(
140+
141+
bucketerParams.logger.log(
142+
LOG_LEVEL.DEBUG,
125143
LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
126144
MODULE_NAME,
127145
bucketValue,
128-
bucketerParams.userId
146+
bucketerParams.userId,
129147
);
130-
bucketerParams.logger.log(LOG_LEVEL.DEBUG, bucketedUserLogMessage);
131-
decideReasons.push(bucketedUserLogMessage);
148+
decideReasons.push([
149+
LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
150+
MODULE_NAME,
151+
bucketValue,
152+
bucketerParams.userId,
153+
]);
132154

133155
const entityId = _findBucket(bucketValue, bucketerParams.trafficAllocationConfig);
134156
if (entityId !== null) {
135157
if (!bucketerParams.variationIdMap[entityId]) {
136-
if (entityId) {
137-
const invalidVariationIdLogMessage = sprintf(LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME);
138-
bucketerParams.logger.log(LOG_LEVEL.WARNING, invalidVariationIdLogMessage);
139-
decideReasons.push(invalidVariationIdLogMessage);
158+
if (entityId) {
159+
bucketerParams.logger.log(LOG_LEVEL.WARNING, LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME);
160+
decideReasons.push([LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME]);
140161
}
141162
return {
142163
result: null,
@@ -165,11 +186,14 @@ export const bucketUserIntoExperiment = function(
165186
userId: string,
166187
logger: LogHandler
167188
): string | null {
168-
const bucketingKey = sprintf('%s%s', bucketingId, group.id);
189+
const bucketingKey = `${bucketingId}${group.id}`;
169190
const bucketValue = _generateBucketValue(bucketingKey);
170191
logger.log(
171192
LOG_LEVEL.DEBUG,
172-
sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, MODULE_NAME, bucketValue, userId)
193+
LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
194+
MODULE_NAME,
195+
bucketValue,
196+
userId,
173197
);
174198
const trafficAllocationConfig = group.trafficAllocation;
175199
const bucketedExperimentId = _findBucket(bucketValue, trafficAllocationConfig);

0 commit comments

Comments
 (0)