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.

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

Fix search telemetry to only update SO periodically #93130

Merged
merged 18 commits into from
Mar 11, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
18 changes: 0 additions & 18 deletions api_docs/case.mdx

This file was deleted.

6 changes: 3 additions & 3 deletions api_docs/cases.json
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
{
"id": "case",
"id": "cases",
"client": {
"classes": [],
"functions": [],
Expand Down Expand Up @@ -34,7 +34,7 @@
{
"pluginId": "cases",
"scope": "server",
"docId": "kibCasePluginApi",
"docId": "kibCasesPluginApi",
"section": "def-server.CasesClient",
"text": "CasesClient"
}
Expand All @@ -60,4 +60,4 @@
"misc": [],
"objects": []
}
}
}
18 changes: 18 additions & 0 deletions api_docs/cases.mdx
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
---
id: kibCasesPluginApi
slug: /kibana-dev-docs/casesPluginApi
title: cases
image: https://source.unsplash.com/400x175/?github
summary: API docs for the cases plugin
date: 2020-11-16
tags: ['contributor', 'dev', 'apidocs', 'kibana', 'cases']
warning: This document is auto-generated and is meant to be viewed inside our experimental, new docs system. Reach out in #docs-engineering for more info.
---

import casesObj from './cases.json';

## Server

### Interfaces
<DocDefinitionList data={casesObj.server.interfaces}/>

35 changes: 31 additions & 4 deletions api_docs/data_search.json
Original file line number Diff line number Diff line change
Expand Up @@ -1435,7 +1435,15 @@
"section": "def-server.SearchUsage",
"text": "SearchUsage"
},
" | undefined) => { next(response: ",
" | undefined, { isRestore }: ",
{
"pluginId": "data",
"scope": "common",
"docId": "kibDataSearchPluginApi",
"section": "def-common.ISearchOptions",
"text": "ISearchOptions"
},
") => { next(response: ",
{
"pluginId": "data",
"scope": "common",
Expand All @@ -1459,7 +1467,7 @@
"description": [],
"source": {
"path": "src/plugins/data/server/search/collectors/usage.ts",
"lineNumber": 64
"lineNumber": 83
}
},
{
Expand All @@ -1479,15 +1487,34 @@
"description": [],
"source": {
"path": "src/plugins/data/server/search/collectors/usage.ts",
"lineNumber": 64
"lineNumber": 84
}
},
{
"type": "Object",
"label": "{ isRestore }",
"isRequired": true,
"signature": [
{
"pluginId": "data",
"scope": "common",
"docId": "kibDataSearchPluginApi",
"section": "def-common.ISearchOptions",
"text": "ISearchOptions"
}
],
"description": [],
"source": {
"path": "src/plugins/data/server/search/collectors/usage.ts",
"lineNumber": 85
}
}
],
"tags": [],
"returnComment": [],
"source": {
"path": "src/plugins/data/server/search/collectors/usage.ts",
"lineNumber": 64
"lineNumber": 82
},
"initialIsOpen": false
},
Expand Down
16 changes: 16 additions & 0 deletions api_docs/lists.json
Original file line number Diff line number Diff line change
Expand Up @@ -4489,6 +4489,22 @@
],
"initialIsOpen": false
},
{
"tags": [],
"id": "def-common.osType",
"type": "Object",
"label": "osType",
"description": [],
"source": {
"path": "x-pack/plugins/lists/common/schemas/common/schemas.ts",
"lineNumber": 317
},
"signature": [
"KeyofC",
"<{ linux: null; macos: null; windows: null; }>"
],
"initialIsOpen": false
},
{
"tags": [],
"id": "def-common.osTypeArray",
Expand Down
8 changes: 4 additions & 4 deletions api_docs/security_solution.json
Original file line number Diff line number Diff line change
Expand Up @@ -607,7 +607,7 @@
"description": [],
"source": {
"path": "x-pack/plugins/security_solution/server/plugin.ts",
"lineNumber": 336
"lineNumber": 337
}
},
{
Expand All @@ -626,15 +626,15 @@
"description": [],
"source": {
"path": "x-pack/plugins/security_solution/server/plugin.ts",
"lineNumber": 336
"lineNumber": 337
}
}
],
"tags": [],
"returnComment": [],
"source": {
"path": "x-pack/plugins/security_solution/server/plugin.ts",
"lineNumber": 336
"lineNumber": 337
}
},
{
Expand All @@ -650,7 +650,7 @@
"returnComment": [],
"source": {
"path": "x-pack/plugins/security_solution/server/plugin.ts",
"lineNumber": 397
"lineNumber": 398
}
}
],
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@
| [getTime(indexPattern, timeRange, options)](./kibana-plugin-plugins-data-server.gettime.md) | |
| [parseInterval(interval)](./kibana-plugin-plugins-data-server.parseinterval.md) | |
| [plugin(initializerContext)](./kibana-plugin-plugins-data-server.plugin.md) | Static code to be shared externally |
| [searchUsageObserver(logger, usage)](./kibana-plugin-plugins-data-server.searchusageobserver.md) | Rxjs observer for easily doing <code>tap(searchUsageObserver(logger, usage))</code> in an rxjs chain. |
| [searchUsageObserver(logger, usage, { isRestore })](./kibana-plugin-plugins-data-server.searchusageobserver.md) | Rxjs observer for easily doing <code>tap(searchUsageObserver(logger, usage))</code> in an rxjs chain. |
| [shouldReadFieldFromDocValues(aggregatable, esType)](./kibana-plugin-plugins-data-server.shouldreadfieldfromdocvalues.md) | |
| [usageProvider(core)](./kibana-plugin-plugins-data-server.usageprovider.md) | |

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ Rxjs observer for easily doing `tap(searchUsageObserver(logger, usage))` in an r
<b>Signature:</b>

```typescript
export declare function searchUsageObserver(logger: Logger, usage?: SearchUsage): {
export declare function searchUsageObserver(logger: Logger, usage?: SearchUsage, { isRestore }?: ISearchOptions): {
next(response: IEsSearchResponse): void;
error(): void;
};
Expand All @@ -21,6 +21,7 @@ export declare function searchUsageObserver(logger: Logger, usage?: SearchUsage)
| --- | --- | --- |
| logger | <code>Logger</code> | |
| usage | <code>SearchUsage</code> | |
| { isRestore } | <code>ISearchOptions</code> | |

<b>Returns:</b>

Expand Down
83 changes: 53 additions & 30 deletions src/plugins/data/server/search/collectors/usage.ts
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,13 @@
* Side Public License, v 1.
*/

import { once } from 'lodash';
import { once, debounce } from 'lodash';
import type { CoreSetup, Logger } from 'kibana/server';
import { SavedObjectsErrorHelpers } from '../../../../../core/server';
import type { IEsSearchResponse } from '../../../common';
import type { IEsSearchResponse, ISearchOptions } from '../../../common';
import { isCompleteResponse } from '../../../common';
import { CollectedUsage } from './register';

const SAVED_OBJECT_ID = 'search-telemetry';
const MAX_RETRY_COUNT = 3;

export interface SearchUsage {
trackError(): Promise<void>;
Expand All @@ -25,34 +25,52 @@ export function usageProvider(core: CoreSetup): SearchUsage {
return coreStart.savedObjects.createInternalRepository();
});

const trackSuccess = async (duration: number, retryCount = 0) => {
const repository = await getRepository();
try {
await repository.incrementCounter(SAVED_OBJECT_ID, SAVED_OBJECT_ID, [
{ fieldName: 'successCount' },
{
fieldName: 'totalDuration',
incrementBy: duration,
},
]);
} catch (e) {
if (SavedObjectsErrorHelpers.isConflictError(e) && retryCount < MAX_RETRY_COUNT) {
setTimeout(() => trackSuccess(duration, retryCount + 1), 1000);
}
}
const collectedUsage: CollectedUsage = {
successCount: 0,
Copy link
Contributor

Choose a reason for hiding this comment

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

nit: we are dynamically mapping these fields into telemetry objects. I wonder if this dynamic mapping makes it very easy to change field names without realizing that this breaks about telemetry logs structure.

Copy link
Contributor

Choose a reason for hiding this comment

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

I wonder if this might have some implications if we work in clustering mode 🤔
#68626

errorCount: 0,
totalDuration: 0,
};

const trackError = async (retryCount = 0) => {
const repository = await getRepository();
try {
await repository.incrementCounter(SAVED_OBJECT_ID, SAVED_OBJECT_ID, [
{ fieldName: 'errorCount' },
]);
} catch (e) {
if (SavedObjectsErrorHelpers.isConflictError(e) && retryCount < MAX_RETRY_COUNT) {
setTimeout(() => trackError(retryCount + 1), 1000);
// Instead of updating the search count every time a search completes, we update some in-memory
// counts and only update the saved object every ~5 seconds
const updateSearchUsage = debounce(
async () => {
const repository = await getRepository();
const { successCount, errorCount, totalDuration } = collectedUsage;
const counterFields = Object.entries(collectedUsage)
.map(([fieldName, incrementBy]) => ({ fieldName, incrementBy }))
// Filter out any zero values because `incrementCounter` will still increment them
.filter(({ incrementBy }) => incrementBy > 0);

try {
await repository.incrementCounter<CollectedUsage>(
Copy link
Contributor

@Dosant Dosant Mar 10, 2021

Choose a reason for hiding this comment

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

nit: Could it be that repository.incrementCounter took so long that the next request is starting? In this case, the next request will pick up incorrect stats.
I assume this won't happen as 5 seconds is a huge margin and we can leave it as is.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah, I guess that's a possible edge case. I would think Kibana would be pretty much unusable if an incrementCounter request takes more than 5s, so we'll leave it as is for now.

SAVED_OBJECT_ID,
SAVED_OBJECT_ID,
counterFields
);

// Since search requests may have completed while the saved object was being updated, we minus
// what was just updated in the saved object rather than resetting the values to 0
collectedUsage.successCount -= successCount;
collectedUsage.errorCount -= errorCount;
collectedUsage.totalDuration -= totalDuration;
} catch (e) {
// We didn't reset the counters so we'll retry when the next search request completes
}
}
},
5000,
{ maxWait: 5000 }
);

const trackSuccess = (duration: number) => {
collectedUsage.successCount++;
collectedUsage.totalDuration += duration;
return updateSearchUsage();
};

const trackError = () => {
collectedUsage.errorCount++;
return updateSearchUsage();
};

return { trackSuccess, trackError };
Expand All @@ -61,9 +79,14 @@ export function usageProvider(core: CoreSetup): SearchUsage {
/**
* Rxjs observer for easily doing `tap(searchUsageObserver(logger, usage))` in an rxjs chain.
*/
export function searchUsageObserver(logger: Logger, usage?: SearchUsage) {
export function searchUsageObserver(
logger: Logger,
usage?: SearchUsage,
{ isRestore }: ISearchOptions = {}
) {
return {
next(response: IEsSearchResponse) {
if (isRestore || !isCompleteResponse(response)) return;
logger.debug(`trackSearchStatus:next ${response.rawResponse.took}`);
usage?.trackSuccess(response.rawResponse.took);
Copy link
Contributor

Choose a reason for hiding this comment

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

Probably not related to this pr, but I want to point out:

When we restore a search session then this took is the original time that query took.

so assume:

  1. Doing a search the first time - Request completes in ~10ms and took is 10ms
  2. Restoring a search session - Request completes ~3ms and took is still 10ms

I wonder if we actually want to track this took here

Copy link
Member Author

Choose a reason for hiding this comment

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

Good point, we probably don't want to track at all if isRestore is set to true.

},
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,6 @@ export const esSearchStrategyProvider = (
}
};

return from(search()).pipe(tap(searchUsageObserver(logger, usage)));
return from(search()).pipe(tap(searchUsageObserver(logger, usage, options)));
},
});
2 changes: 1 addition & 1 deletion src/plugins/data/server/server.api.md
Original file line number Diff line number Diff line change
Expand Up @@ -1350,7 +1350,7 @@ export interface SearchUsage {
// Warning: (ae-missing-release-tag) "searchUsageObserver" is exported by the package, but it is missing a release tag (@alpha, @beta, @public, or @internal)
//
// @public
export function searchUsageObserver(logger: Logger_2, usage?: SearchUsage): {
export function searchUsageObserver(logger: Logger_2, usage?: SearchUsage, { isRestore }?: ISearchOptions): {
next(response: IEsSearchResponse): void;
error(): void;
};
Expand Down