Skip to content

Commit

Permalink
Add more variables to query logs (#1049)
Browse files Browse the repository at this point in the history
* Add more variables to query logs

* add custom logger for query viz

* basic tests
  • Loading branch information
adrianmroz-allegro committed Mar 9, 2023
1 parent e4f7b74 commit ca501c2
Show file tree
Hide file tree
Showing 3 changed files with 171 additions and 49 deletions.
52 changes: 3 additions & 49 deletions src/server/routes/query/routes/visualization.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,71 +14,25 @@
* limitations under the License.
*/

import { Duration } from "chronoshift";
import { Response } from "express";
import { Expression } from "plywood";
import makeGridQuery from "../../../../client/visualizations/grid/make-query";
import { Logger } from "../../../../common/logger/logger";
import { Essence } from "../../../../common/models/essence/essence";
import { FixedTimeFilterClause } from "../../../../common/models/filter-clause/filter-clause";
import { usedMeasures } from "../../../../common/models/series/used-measures";
import { Timekeeper } from "../../../../common/models/timekeeper/timekeeper";
import makeQuery from "../../../../common/utils/query/visualization-query";
import { executeQuery } from "../../../utils/query/execute-query";
import { logQueryInfo } from "../../../utils/query/log-query";
import { QueryRouterRequest } from "../query";

function getQuery(essence: Essence, timekeeper: Timekeeper): Expression {
return essence.visualization.name === "grid" ? makeGridQuery(essence, timekeeper) : makeQuery(essence, timekeeper);
}

function start(clause: FixedTimeFilterClause): string {
return clause.values.first().start.toUTCString();
}

function intervalLength(clause: FixedTimeFilterClause): number {
const timeRange = clause.values.first();
return timeRange.end.getTime() - timeRange.start.getTime();
}

function timeVariables(essence: Essence, timekeeper: Timekeeper): Record<string, unknown> {
const timeFilter = essence.currentTimeFilter(timekeeper);
const timeDimension = essence.getTimeDimension();
const timeSplit = essence.splits.findSplitForDimension(timeDimension);

const startTime = start(timeFilter);
const interval = intervalLength(timeFilter);

const variables: Record<string, unknown> = { startTime, interval };

if (timeSplit && timeSplit.bucket instanceof Duration) {
variables.granularity = timeSplit.bucket.getDescription();
}

if (essence.hasComparison()) {
const previousTimeFilter = essence.previousTimeFilter(timekeeper);
variables.shiftedStartTime = start(previousTimeFilter);
}

return variables;
}

function logQueryInfo(essence: Essence, timekeeper: Timekeeper, logger: Logger) {
const nonTimeFilters = essence.filter.removeClause(essence.getTimeDimension().name);

logger.log(`Visualization query ${essence.description(timekeeper)}`, {
...timeVariables(essence, timekeeper),
dataCube: essence.dataCube.name,
visualization: essence.visualization.name,
filters: nonTimeFilters.clauses.map(clause => clause.reference).toArray(),
splits: essence.splits.splits.map(split => split.reference).toArray(),
measures: essence.series.series.flatMap(usedMeasures).toSet().toArray()
});
}

export default async function visualizationRoute({ context }: QueryRouterRequest, res: Response) {
const { dataCube, essence, decorator, timekeeper, logger } = context;
logQueryInfo(essence, timekeeper, logger);
const query = getQuery(essence, timekeeper);
const queryTimeStart = Date.now();
const result = await executeQuery(dataCube, query, essence.timezone, decorator);
logQueryInfo(essence, timekeeper, logger.setLoggerId("turnilo-visualization-query"), Date.now() - queryTimeStart);
res.json({ result });
}
88 changes: 88 additions & 0 deletions src/server/utils/query/log-query.mocha.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
/*
* Copyright 2017-2022 Allegro.pl
*
* Licensed 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.
*/

import { expect } from "chai";
import Sinon, { spy } from "sinon";
import { Logger } from "../../../common/logger/logger";
import { VisStrategy } from "../../../common/models/essence/essence";
import { EssenceFixtures } from "../../../common/models/essence/essence.fixtures";
import { measureSeries } from "../../../common/models/series/series.fixtures";
import { timeSplitCombine } from "../../../common/models/split/split.fixtures";
import { TimeShift } from "../../../common/models/time-shift/time-shift";
import { TimekeeperFixtures } from "../../../common/models/timekeeper/timekeeper.fixtures";
import { logQueryInfo } from "./log-query";

describe("log-query-info", () => {
const logger: Logger & { log: Sinon.SinonSpy } = {} as any;

beforeEach(() => {
logger.log = spy();
});

const baseEssence = EssenceFixtures.wikiTotals().addSeries(measureSeries("added"));
const timekeeper = TimekeeperFixtures.wiki();
const executionTime = 42;

const expectedMessage = "Visualization query wiki_2016-04-29-12-40_2016-04-30-12-40";
const expectedBasicVariables: Record<string, unknown> = {
executionTime: 42,
startTime: 1461933600000,
startTimeMsAgo: 86391350,
interval: 86400000,
dataCube: "wiki",
visualization: "totals",
filters: ["commentLength"],
splits: [],
measures: ["added"]
};

it("Should log all basic variables", () => {
logQueryInfo(baseEssence, timekeeper, logger, executionTime);
expect(logger.log.calledWith(
expectedMessage,
expectedBasicVariables
)).to.be.true;
});

it("Should log additional time shift variables", () => {
const essence = baseEssence.set("timeShift", TimeShift.fromJS("P1D"));
logQueryInfo(essence, timekeeper, logger, executionTime);
expect(logger.log.calledWith(
expectedMessage,
{
...expectedBasicVariables,
timeShift: "P1D",
shiftedStartTime: 1461847200000,
shiftedStartTimeMsAgo: 172791350
}
)).to.be.true;
});

it("Should log additional time split variables", () => {
const essence = baseEssence.addSplit(timeSplitCombine("time", "P2D"), VisStrategy.FairGame);
logQueryInfo(essence, timekeeper, logger, executionTime);
expect(logger.log.calledWith(
expectedMessage,
{
...expectedBasicVariables,
visualization: "line-chart",
splits: ["time"],
granularity: "P2D"
}
)).to.be.true;
});

});
80 changes: 80 additions & 0 deletions src/server/utils/query/log-query.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,80 @@
/*
* Copyright 2017-2022 Allegro.pl
*
* Licensed 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.
*/

import { Duration } from "chronoshift";
import { Logger } from "../../../common/logger/logger";
import { getMaxTime } from "../../../common/models/data-cube/data-cube";
import { Essence } from "../../../common/models/essence/essence";
import { FixedTimeFilterClause } from "../../../common/models/filter-clause/filter-clause";
import { usedMeasures } from "../../../common/models/series/used-measures";
import { Timekeeper } from "../../../common/models/timekeeper/timekeeper";

function start(clause: FixedTimeFilterClause): Date {
return clause.values.first().start;
}

function intervalLength(start: Date, end: Date): number {
return end.getTime() - start.getTime();
}

function clauseInterval(clause: FixedTimeFilterClause): number {
const { end, start } = clause.values.first();
return intervalLength(start, end);
}

function timeVariables(essence: Essence, timekeeper: Timekeeper): Record<string, unknown> {
const maxTime = getMaxTime(essence.dataCube, timekeeper);
const timeFilter = essence.currentTimeFilter(timekeeper);
const timeDimension = essence.getTimeDimension();
const timeSplit = essence.splits.findSplitForDimension(timeDimension);

const startTime = start(timeFilter);
const interval = clauseInterval(timeFilter);

const variables: Record<string, unknown> = {
startTime: startTime.getTime(),
startTimeMsAgo: intervalLength(startTime, maxTime),
interval
};

if (timeSplit && timeSplit.bucket instanceof Duration) {
variables.granularity = timeSplit.bucket.toString();
}

if (essence.hasComparison()) {
const previousTimeFilter = essence.previousTimeFilter(timekeeper);
const shiftedStartTime = start(previousTimeFilter);
variables.shiftedStartTime = shiftedStartTime.getTime();
variables.shiftedStartTimeMsAgo = intervalLength(shiftedStartTime, maxTime);
variables.timeShift = essence.timeShift.toString();
}

return variables;
}

export function logQueryInfo(essence: Essence, timekeeper: Timekeeper, logger: Logger, executionTime: number) {
const nonTimeFilters = essence.filter.removeClause(essence.getTimeDimension().name);

logger.log(`Visualization query ${essence.description(timekeeper)}`, {
executionTime,
...timeVariables(essence, timekeeper),
dataCube: essence.dataCube.name,
visualization: essence.visualization.name,
filters: nonTimeFilters.clauses.map(clause => clause.reference).toArray(),
splits: essence.splits.splits.map(split => split.reference).toArray(),
measures: essence.series.series.flatMap(usedMeasures).toSet().toArray()
});
}

0 comments on commit ca501c2

Please sign in to comment.