metrics make request 10x times slower #313
Comments
|
Each step |
|
Which versions?
|
|
I've just measured this demo with jMeter: |
|
I think i found the problem. if i start the process which listen those "metrics" event(metrics.trace.span.start/finish), then whole system slow to "120ms" each request(the event handler is very simple, i even try empty function). if i stop the listen process, the whole system back to normal "10ms" each request. |
|
version:0.12.8 |
|
And the listener is on the same node, or in a remote node? |
|
a remote node, every service in this issue are running on a separate node process |
|
Ok, I will investigate it. |
|
by the way, transporter is "nats" |
|
What I measured: Btw, it was just a simple "test.hello" action. |
yes, that's the problem. my scenario has Maybe you should test its latency? |
|
If you can make a repro repo. |
|
you just make request like this: yes, I can create a repo. But do you need that ? you already measured that remote node listen |
|
It's reasonable that metric function needs extra performance which increases the response time. Unfortunately, in your case, it's a huge difference because every action call generates 2 extra events what need to be transferred to another node which causes overhead. The bad news that I can't fix it currently because it is not a bug it's a design issue. In the version 0.14, I will rewrite the whole metrics & tracing logic to be more efficient and pluggable. |
|
Maybe its not about the In listener node: events: {
// "metrics.trace.span.start": this.traceStart,
// "metrics.trace.span.finish": this.traceFinish,
"event.test.t1": this.t1,
"event.test.t2": this.t2,
},
async t1(info) {
this.logger.info(`${this.name} t1: `, util.inspect(info));
}
async t2(info) {
this.logger.info(`${this.name} t2: `, util.inspect(info));
}in auth: async authorize(ctx) {
this.broker.emit("event.test.t1", {
a: "abc",
b: 123,
c: true
})
console.log("call authorize ctx.params = ", ctx.params)
if (ctx.params.action.indexOf('$node') >= 0) { //disable call $node.*
return false
}
return true
}in demo: async welcome(ctx) {
this.broker.emit("event.test.t2", {
a: "abc",
b: 123,
c: true
})
// await ctx.call('demo.hello')
return this._sayWelcome(ctx.params.name);
}the result is: |
|
simple event take |
|
I guess the problem is not about how to generate metrics. |
|
Hmm, it's weird. Please create a dev example file with 3 brokers & services & NATS like here and I will try to investigate it. |
|
OK, i will create a dev example file |
|
OK, finished call demo1.hello1 at: 1530627615760
call demo2.hello2 at: 1530627615761
call demo3.hello3 at: 1530627615762
call demo1.hello1 use time = 6
call demo1.hello1WithEvent at: 1530627615765
listen t1 at: 1530627615765
call demo2.hello2WithEvent at: 1530627615804
listen t2 at: 1530627615805
call demo3.hello3WithEvent at: 1530627615844
listen t3 at: 1530627615844
call demo1.hello1WithEvent use time = 120test code is: const { ServiceBroker } = require("moleculer");
let natsTransporter = {
type: "NATS",
options: {
url: "nats://127.0.0.1:4222",
}
}
// Create broker Client
const brokerClient = new ServiceBroker({
namespace: "streaming",
nodeID: "client",
transporter: natsTransporter,
logger: console,
logLevel: "info"
});
// Create broker #1
const broker1 = new ServiceBroker({
namespace: "streaming",
nodeID: "demo1",
transporter: natsTransporter,
logger: console,
logLevel: "info"
});
// Create broker #2
const broker2 = new ServiceBroker({
namespace: "streaming",
nodeID: "demo2",
transporter: natsTransporter,
logger: console,
logLevel: "info"
});
// Create broker #3
const broker3 = new ServiceBroker({
namespace: "streaming",
nodeID: "demo3",
transporter: natsTransporter,
logger: console,
logLevel: "info"
});
// Create brokerListen
const brokerListen = new ServiceBroker({
namespace: "streaming",
nodeID: "listen",
transporter: natsTransporter,
logger: console,
logLevel: "info"
});
broker1.createService({
name: "demo1",
actions: {
hello1(ctx) {
console.log("call demo1.hello1 at: ", Date.now())
return ctx.call('demo2.hello2')
},
hello1WithEvent(ctx) {
broker1.emit('t1', { a: 'abc', b: 123, c: true })
console.log("call demo1.hello1WithEvent at: ", Date.now())
return ctx.call('demo2.hello2WithEvent')
}
}
});
broker2.createService({
name: "demo2",
actions: {
hello2(ctx) {
console.log("call demo2.hello2 at: ", Date.now())
return ctx.call('demo3.hello3')
},
hello2WithEvent(ctx) {
broker2.emit('t2', { a: 'abc', b: 123, c: true })
console.log("call demo2.hello2WithEvent at: ", Date.now())
return ctx.call('demo3.hello3WithEvent')
}
}
});
broker3.createService({
name: "demo3",
actions: {
hello3(ctx) {
console.log("call demo3.hello3 at: ", Date.now())
return "hello from demo3"
},
hello3WithEvent(ctx) {
broker3.emit('t3', { a: 'abc', b: 123, c: true })
console.log("call demo3.hello3WithEvent at: ", Date.now())
return "hello from hello3WithEvent"
}
}
});
brokerListen.createService({
name: "listen",
events: {
t1: (ctx) => {
console.log("listen t1 at: ", Date.now())
},
t2: (ctx) => {
console.log("listen t2 at: ", Date.now())
},
t3: (ctx) => {
console.log("listen t3 at: ", Date.now())
},
}
});
brokerClient.Promise.all([brokerClient.start(), broker1.start(), broker2.start(), broker3.start(), brokerListen.start()])
.delay(2000)
.then(async () => {
let startTime = Date.now()
await brokerClient.call('demo1.hello1')
let endTime = Date.now()
console.log("call demo1.hello1 use time = ", endTime - startTime)
startTime = Date.now()
await brokerClient.call('demo1.hello1WithEvent')
endTime = Date.now()
console.log("call demo1.hello1WithEvent use time = ", endTime - startTime)
// startTime = Date.now()
// await brokerClient.call('demo1.hello1WithEvent')
// endTime = Date.now()
// console.log("call demo1.hello1WithEvent again use time = ", endTime - startTime)
}); |
|
Thanks, I will investigate it tonight. |
|
It's weirder. It's the result on my PC: |
|
Node version, OS, architecture...etc? |
|
I could reproduce it on Ubuntu |
|
It's very mystic! And it's only on Linux. On Windows it's ~1500-2000 rps with all transporters.
|
|
have you try different nats client library version? |
|
I will, but currently I can't. |
|
I tried with 0.8, 0.7...same result. |
|
Same thing here.
Info about my system: Kubuntu 18.04 64bit NodeJS: 8.11.3 |
|
Thanks @AndreMaz |
|
After long time digging and testing, i found the reason. I don't know its
Just modify this file at: // Create the stream
this.stream = net.createConnection(this.url.port, this.url.hostname);
this.stream.setNoDelay(true) // need call it, somehow default 'true' is not workAfter manually add test environment: |
|
Wow, nice catch! It can explain why has the difference between OSs. So on Windows, the noDelay can be |
|
And it's the reason why was not problem with Redis transporter: |
|
Btw, I can add a workaround, that I set the |
|
@icebob Maybe you should also listen client.on("connect", () => {
this.client = client;
if (client.stream)
client.stream.setNoDelay(true);
client.on("reconnect", () => {
this.client = client;
if (client.stream)
client.stream.setNoDelay(true); |
|
Yes, good idea! |
|
npm already has a fix for this, you may want to just update and remove the patching. |
|
@aricart Thank you for fixing this |
|
@roytan883 yw!! |
The issue scenario is :
apiGateway.rest -> auth.authorize->demo.welcome->demo.helloevery step is very simple, should only consider network cost.
If i enable
metrics: truein each services process, use about120mstotal. Buf if i disablemetrics, it only use about10ms.metricsinternal use event broadcast ? Then is should not impact normal performance so badly.The text was updated successfully, but these errors were encountered: