Skip to content

Execution logger #83

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

Closed
wants to merge 14 commits into from
Closed
Show file tree
Hide file tree
Changes from 3 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
3 changes: 1 addition & 2 deletions package.json
Original file line number Diff line number Diff line change
Expand Up @@ -72,10 +72,9 @@
"chromium-bidi": "^0.12.0",
"dotenv": "^16.0.0",
"html2canvas": "^1.4.1",
"loglevel": "^1.9.2",
"openai": "^4.77.0",
"playwright": "^1.49.1",
"rotating-file-stream": "^3.2.6",
"tslog": "^4.9.3",
"uuid": "^11.0.3",
"zod": "^3.22.4"
},
Expand Down
5 changes: 3 additions & 2 deletions src/common/chrome/proxy.ts
Original file line number Diff line number Diff line change
Expand Up @@ -21,9 +21,10 @@
* ```
* In this example, `tabs_get` is a mock implementation that logs the `tabId` before calling the original `chrome.tabs.get` method, and the same as `chrome.windows.create` method.
*/
import { logger } from '../log';
export function createChromeApiProxy(mockClass: any): any {
console.log("debug mockClass:");
console.log(mockClass);
logger.debug("debug mockClass:");
logger.debug(mockClass);

return new Proxy(chrome, {
get(target: any, prop: string | symbol) {
Expand Down
52 changes: 24 additions & 28 deletions src/common/log.ts
Original file line number Diff line number Diff line change
@@ -1,47 +1,43 @@
import { Logger, ILogObj } from 'tslog';
import { join } from 'path';
import { tmpdir } from 'os';
import log from 'loglevel';

export class EkoLogger {
private logger: Logger<ILogObj>;
private logFilePath: string;
private logger: log.Logger;
private logStorage: string[] = [];
Copy link
Collaborator

Choose a reason for hiding this comment

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

潜在的性能瓶颈?当大量日志涌入时,这里的性能会不会过慢而拖慢整个工作流的后腿?问一下 AI。

Copy link
Contributor Author

@1579923417 1579923417 Mar 4, 2025

Choose a reason for hiding this comment

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

在高并发或大量日志的情况下,这段代码确实会存在性能瓶颈。

1. 性能瓶颈分析

(1)日志存储(logStorage

logStorage 是一个数组,用于存储所有日志内容。随着日志数量的增加,logStorage 的大小会不断增长,这可能导致以下问题:

  • 内存占用:大量日志会导致内存占用快速上升,尤其是在长时间运行的应用中。
  • 数组操作性能:每次调用 logStorage.push() 时,数组会动态扩展,这在 JavaScript 中可能涉及内存重新分配。当数组非常大时,频繁的内存分配和扩展会显著降低性能。
  • 垃圾回收压力:大量的日志数据可能导致频繁的垃圾回收,进一步影响应用性能。

(2)日志内容截断和序列化

toReadableString() 方法中,对日志内容进行了截断和序列化:

  • JSON 序列化JSON.stringify() 是一个相对较慢的操作,尤其是对于复杂对象。在高并发场景下,大量调用 JSON.stringify() 可能会拖慢性能。
  • 并且这里toReadableString的方法不能很好地处理嵌套对象,无法达到预期的效果(没有进行截断),目前修改了几版代码还是无法解决这个问题。

2. 优化建议

限制日志存储大小

  • 固定大小的存储:可以将 logStorage 设计为一个固定大小的存储结构,例如使用环形缓冲区(FIFO 队列)。当存储满时,自动丢弃最早的日志。
  • 日志采样:在高并发场景下,可以对日志进行采样,只记录部分日志,而不是所有日志。

Copy link
Collaborator

Choose a reason for hiding this comment

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

我让你问 AI 不是因为我懒得问,是因为我想让你参考 AI 的回复来决定是否修改这里的实现……


constructor() {
const now = new Date();
const timestamp = now.toISOString().replace(/[-:.TZ]/g, '').slice(0, 14);

const logFileName = `Eko-${timestamp}.log`;
this.logFilePath = join(tmpdir(), logFileName);

this.logger = new Logger({
name: "EkoLog",
overwrite: {
mask: (...args: any[]): unknown[] => {
return args.map((arg) => {
return this.toReadableString(arg);
});
},
},
});

// log file path
this.logger.info(`log file path at: ${this.logFilePath}`);
}
this.logger = log.getLogger('EkoLogger');
this.logger.setLevel(log.levels.TRACE);

const originalFactory = this.logger.methodFactory;

this.logger.methodFactory = (methodName, logLevel, loggerName) => {
const rawMethod = originalFactory(methodName, logLevel, loggerName);
return (...args: any[]) => {
const truncatedArgs = args.map(arg => this.toReadableString(arg));
this.logStorage.push(`[${methodName.toUpperCase()}] ${truncatedArgs.join(' ')}`);
rawMethod(...truncatedArgs);
};
};

}
// truncate content if it exceeds 2048 characters
private toReadableString(content: any): string {
const contentString = JSON.stringify(content);
const maxLength = 2048;
if (contentString.length > maxLength) {
return contentString.substring(0, maxLength) + '...';
return contentString.substring(0, maxLength - 3) + '...';
} else {
return contentString;
}
}

public getLogger(): Logger<ILogObj> {
public getLoggerInstance(): log.Logger {
return this.logger;
}

public getAllLogs(): string[] {
return this.logStorage;
}
}

export const logger = new EkoLogger().getLogger();
export const logger = new EkoLogger().getLoggerInstance();
5 changes: 3 additions & 2 deletions src/common/tools/summary_workflow.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
import { SummaryWorkflowInput } from '../../types/tools.types';
import { Tool, InputSchema, ExecutionContext } from '../../types/action.types';
import { logger } from '../log';

export class SummaryWorkflow implements Tool<SummaryWorkflowInput, any> {
name: string;
Expand Down Expand Up @@ -29,8 +30,8 @@ export class SummaryWorkflow implements Tool<SummaryWorkflowInput, any> {
if (typeof params !== 'object' || params === null || !params.summary) {
throw new Error('Invalid parameters. Expected an object with a "summary" property.');
}
console.log("isSuccessful: " + params.isSuccessful);
console.log("summary: " + params.summary);
logger.debug("isSuccessful: " + params.isSuccessful);
logger.debug("summary: " + params.summary);
context.variables.set("workflow_is_successful", params.isSuccessful);
context.variables.set("workflow_summary", params.summary);
await context.callback?.hooks.onSummaryWorkflow?.(params.summary);
Expand Down
6 changes: 3 additions & 3 deletions src/core/eko.ts
Original file line number Diff line number Diff line change
Expand Up @@ -27,15 +27,15 @@ export class Eko {
private workflowGeneratorMap = new Map<Workflow, WorkflowGenerator>();

constructor(llmConfig: LLMConfig, ekoConfig?: EkoConfig) {
console.info("using Eko@" + process.env.COMMIT_HASH);
logger.info("using Eko@" + process.env.COMMIT_HASH);
this.llmProvider = LLMProviderFactory.buildLLMProvider(llmConfig);
this.ekoConfig = this.buildEkoConfig(ekoConfig);
this.registerTools();
}

private buildEkoConfig(ekoConfig: Partial<EkoConfig> | undefined): EkoConfig {
if (!ekoConfig) {
console.warn("`ekoConfig` is missing when construct `Eko` instance");
logger.warn("`ekoConfig` is missing when construct `Eko` instance");
}
return {
...DefaultEkoConfig,
Expand Down Expand Up @@ -113,7 +113,7 @@ export class Eko {
}

const result = await workflow.execute(this.ekoConfig.callback);
console.log(result);
logger.debug(result);
return result;
}

Expand Down
2 changes: 1 addition & 1 deletion src/extension/script/build_dom_tree.js
Original file line number Diff line number Diff line change
Expand Up @@ -643,7 +643,7 @@ function build_dom_tree(doHighlightElements) {
nodeData.children.push(...iframeChildren);
}
} catch (e) {
console.warn('Unable to access iframe:', node);
logger.warn('Unable to access iframe:', node);
}
} else {
const children = Array.from(node.childNodes).map((child) =>
Expand Down
18 changes: 9 additions & 9 deletions src/extension/tools/browser.ts
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ export async function type_by(
}

export async function clear_input(chromeProxy: any, tabId: number, coordinate?: [number, number]): Promise<any> {
console.log('Sending clear_input message to tab:', tabId, { coordinate });
logger.debug('Sending clear_input message to tab:', tabId, { coordinate });
try {
if (!coordinate) {
coordinate = (await cursor_position(chromeProxy, tabId)).coordinate;
Expand Down Expand Up @@ -93,7 +93,7 @@ export async function clear_input_by(
}

export async function mouse_move(chromeProxy: any, tabId: number, coordinate: [number, number]): Promise<any> {
console.log('Sending mouse_move message to tab:', tabId, { coordinate });
logger.debug('Sending mouse_move message to tab:', tabId, { coordinate });
try {
const response = await chromeProxy.tabs.sendMessage(tabId, {
type: 'computer:mouse_move',
Expand All @@ -108,7 +108,7 @@ export async function mouse_move(chromeProxy: any, tabId: number, coordinate: [n
}

export async function left_click(chromeProxy: any, tabId: number, coordinate?: [number, number]): Promise<any> {
console.log('Sending left_click message to tab:', tabId, { coordinate });
logger.debug('Sending left_click message to tab:', tabId, { coordinate });
try {
if (!coordinate) {
coordinate = (await cursor_position(chromeProxy, tabId)).coordinate;
Expand Down Expand Up @@ -147,7 +147,7 @@ export async function left_click_by(
}

export async function right_click(chromeProxy: any, tabId: number, coordinate?: [number, number]): Promise<any> {
console.log('Sending right_click message to tab:', tabId, { coordinate });
logger.debug('Sending right_click message to tab:', tabId, { coordinate });
try {
if (!coordinate) {
coordinate = (await cursor_position(chromeProxy, tabId)).coordinate;
Expand Down Expand Up @@ -186,7 +186,7 @@ export async function right_click_by(
}

export async function double_click(chromeProxy: any, tabId: number, coordinate?: [number, number]): Promise<any> {
console.log('Sending double_click message to tab:', tabId, { coordinate });
logger.debug('Sending double_click message to tab:', tabId, { coordinate });
try {
if (!coordinate) {
coordinate = (await cursor_position(chromeProxy, tabId)).coordinate;
Expand Down Expand Up @@ -225,7 +225,7 @@ export async function double_click_by(
}

export async function screenshot(chromeProxy: any, windowId: number, compress?: boolean): Promise<ScreenshotResult> {
console.log('Taking screenshot of window:', windowId, { compress });
logger.debug('Taking screenshot of window:', windowId, { compress });
try {
let dataUrl;
if (compress) {
Expand Down Expand Up @@ -289,7 +289,7 @@ export async function compress_image(
}

export async function scroll_to(chromeProxy: any, tabId: number, coordinate: [number, number]): Promise<any> {
console.log('Sending scroll_to message to tab:', tabId, { coordinate });
logger.debug('Sending scroll_to message to tab:', tabId, { coordinate });
try {
let from_coordinate = (await cursor_position(chromeProxy, tabId)).coordinate;
const response = await chromeProxy.tabs.sendMessage(tabId, {
Expand Down Expand Up @@ -387,10 +387,10 @@ export async function cursor_position(chromeProxy: any, tabId: number): Promise<
}

export async function size(chromeProxy: any, tabId?: number): Promise<[number, number]> {
console.log('Getting page size for tab:', tabId);
logger.debug('Getting page size for tab:', tabId);
try {
const pageSize = await getPageSize(chromeProxy, tabId);
console.log('Got page size:', pageSize);
logger.debug('Got page size:', pageSize);
return pageSize;
} catch (e) {
logger.error('Failed to get page size:', e);
Expand Down
18 changes: 9 additions & 9 deletions src/extension/tools/browser_use.ts
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ export class BrowserUse implements Tool<BrowserUseParam, BrowserUseResult> {
* @returns > { success: true, image?: { type: 'base64', media_type: 'image/jpeg', data: '/9j...' }, text?: string }
*/
async execute(context: ExecutionContext, params: BrowserUseParam): Promise<BrowserUseResult> {
console.log("execute 'browser_use'...");
logger.debug("execute 'browser_use'...");
try {
if (params === null || !params.action) {
throw new Error('Invalid parameters. Expected an object with a "action" property.');
Expand Down Expand Up @@ -177,32 +177,32 @@ export class BrowserUse implements Tool<BrowserUseParam, BrowserUseResult> {
);
break;
case 'screenshot_extract_element':
console.log("execute 'screenshot_extract_element'...");
logger.debug("execute 'screenshot_extract_element'...");
await sleep(100);
console.log("injectScript...");
logger.debug("injectScript...");
await injectScript(context.ekoConfig.chromeProxy, tabId, 'build_dom_tree.js');
await sleep(100);
console.log("executeScript...");
logger.debug("executeScript...");
let element_result = await executeScript(context.ekoConfig.chromeProxy, tabId, () => {
return (window as any).get_clickable_elements(true);
}, []);
context.selector_map = element_result.selector_map;
console.log("browser.screenshot...");
logger.debug("browser.screenshot...");
let screenshot = await browser.screenshot(context.ekoConfig.chromeProxy, windowId, true);
console.log("executeScript #2...");
logger.debug("executeScript #2...");
await executeScript(context.ekoConfig.chromeProxy, tabId, () => {
return (window as any).remove_highlight();
}, []);
result = { image: screenshot.image, text: element_result.element_str };
console.log("execute 'screenshot_extract_element'...done");
logger.debug("execute 'screenshot_extract_element'...done");
break;
default:
throw Error(
`Invalid parameters. The "${params.action}" value is not included in the "action" enumeration.`
);
}
console.log("execute 'browser_use'...done, result=");
console.log(result);
logger.debug("execute 'browser_use'...done, result=");
logger.debug(result);
if (result) {
return { success: true, ...result };
} else {
Expand Down
4 changes: 2 additions & 2 deletions src/extension/utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ export async function getWindowId(context: ExecutionContext): Promise<number> {
}

if (!windowId) {
console.warn("`getWindowId()` returns " + windowId);
logger.warn("`getWindowId()` returns " + windowId);
}

return windowId as number;
Expand Down Expand Up @@ -75,7 +75,7 @@ export function getCurrentTabId(chromeProxy: any, windowId?: number | undefined)
return new Promise((resolve, reject) => {
chromeProxy.tabs.query({ windowId, active: true, lastFocusedWindow: true }, function (tabs: any) {
if (chromeProxy.runtime.lastError) {
console.error('Chrome runtime error:', chromeProxy.runtime.lastError);
logger.error('Chrome runtime error:', chromeProxy.runtime.lastError);
reject(chromeProxy.runtime.lastError);
return;
}
Expand Down
8 changes: 4 additions & 4 deletions src/models/workflow.ts
Original file line number Diff line number Diff line change
Expand Up @@ -114,13 +114,13 @@ export class WorkflowImpl implements Workflow {
let node_outputs = terminalNodes.map(node => node.output);

// Special context variables
console.log("debug special context variables...");
logger.debug("debug special context variables...");
const workflowIsSuccessful = this.variables.get("workflow_is_successful");
console.log(workflowIsSuccessful);
logger.debug(workflowIsSuccessful);
const workflowSummary = this.variables.get("workflow_summary");
console.log(workflowSummary);
logger.debug(workflowSummary);
const workflowTranscript = this.variables.get("workflow_transcript");
console.log(workflowTranscript);
logger.debug(workflowTranscript);

return {
isSuccessful: workflowIsSuccessful as boolean,
Expand Down
4 changes: 3 additions & 1 deletion src/nodejs/script/build_dom_tree.js
Original file line number Diff line number Diff line change
@@ -1,3 +1,5 @@
import { logger } from "@/common/log";

export function run_build_dom_tree() {
/**
* Get clickable elements on the page
Expand Down Expand Up @@ -644,7 +646,7 @@ export function run_build_dom_tree() {
nodeData.children.push(...iframeChildren);
}
} catch (e) {
console.warn('Unable to access iframe:', node);
logger.warn('Unable to access iframe:', node);
}
} else {
const children = Array.from(node.childNodes).map((child) =>
Expand Down
6 changes: 3 additions & 3 deletions src/services/workflow/generator.ts
Original file line number Diff line number Diff line change
Expand Up @@ -93,8 +93,8 @@ export class WorkflowGenerator {
const workflowData = response.toolCalls[0].input.workflow as any;

// debug
console.log("Debug the workflow...")
console.log({ ...workflowData});
logger.debug("Debug the workflow...")
logger.debug({ ...workflowData});

// Add workflow summary subtask
(workflowData.nodes as any[]).push({
Expand All @@ -110,7 +110,7 @@ export class WorkflowGenerator {
]
},
})
console.log("Debug the workflow...Done")
logger.debug("Debug the workflow...Done")

// Validate all tools exist
for (const node of workflowData.nodes) {
Expand Down
35 changes: 0 additions & 35 deletions src/universal_tools/summary_workflow.ts

This file was deleted.

3 changes: 2 additions & 1 deletion src/web/script/build_dom_tree.js
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import { logger } from "@/common/log";
/**
* Get clickable elements on the page
*
Expand Down Expand Up @@ -643,7 +644,7 @@ function build_dom_tree(doHighlightElements) {
nodeData.children.push(...iframeChildren);
}
} catch (e) {
console.warn('Unable to access iframe:', node);
logger.warn('Unable to access iframe:', node);
}
} else {
const children = Array.from(node.childNodes).map((child) =>
Expand Down