Open jhuckaby opened 5 years ago
I can reproduce this with canvas-prebuilt@1.6 also (on macOS 10.13.6).
When you tried 1.6, were you building from source (the default) or using canvas-prebuilt? Can you try 2.x with npm install --build-from-source
? (That flag doesn't work with yarn AFAIK.) If it's a difference between built-from-source and prebuilds, then @chearon might have ideas. I only have a Mac VM that I'm not a sudoer on, so I'm pretty useless as far as investigating, but I'm guessing it's slow dynamic linking.
Using node --prof
:
[Summary]:
ticks total nonlib name
6 1.4% 1.4% JavaScript
110 25.6% 25.9% C++
4 0.9% 0.9% GC
5 1.2% Shared libraries
308 71.8% Unaccounted <-- suspicious
With the v8 profiler, CanvasPattern
shows up as the longest span in 2.x, and FontFace
in 1.x, which I think are red herrings.
I don't know if dyld's calls are captured with dtrace (dtruss), but that could be useful to look at. You can also use env vars to control dyld logging. Maybe the diff of the output from DYLD_PRINT_LIBRARIES
or DYLD_PRINT_BINDINGS
between the slow and the fast version would be useful.
Another useful thing could be to time the entire process execution (time node ./test.js
), in case those ~400 ms are being spent in initialization instead of the first instantiation of a canvas.
Thanks, this is great information!
When you tried 1.6, were you building from source (the default) or using canvas-prebuilt?
My canvas v1.6 was indeed built from source, and notably it is without pango as well. I could never get pango to install for v1.6, so I just ran without it.
Can you try 2.x with npm install --build-from-source?
Yup, I sure can. Thankfully, this compiled just fine for me on Mojave (whew!). However, the bug is still reproducible, even when running from the source-compiled library:
Compile Log
mini:canv2-src jhuckaby$ npm install --build-from-source
> canvas@2.3.1 install /Users/jhuckaby/temp/canv2-src/node_modules/canvas
> node-pre-gyp install --fallback-to-build
node-pre-gyp WARN Using needle for node-pre-gyp https download
SOLINK_MODULE(target) Release/canvas-postbuild.node
CXX(target) Release/obj.target/canvas/src/backend/Backend.o
CXX(target) Release/obj.target/canvas/src/backend/ImageBackend.o
CXX(target) Release/obj.target/canvas/src/backend/PdfBackend.o
CXX(target) Release/obj.target/canvas/src/backend/SvgBackend.o
CXX(target) Release/obj.target/canvas/src/bmp/BMPParser.o
CXX(target) Release/obj.target/canvas/src/Backends.o
CXX(target) Release/obj.target/canvas/src/Canvas.o
CXX(target) Release/obj.target/canvas/src/CanvasGradient.o
CXX(target) Release/obj.target/canvas/src/CanvasPattern.o
CXX(target) Release/obj.target/canvas/src/CanvasRenderingContext2d.o
CXX(target) Release/obj.target/canvas/src/closure.o
CXX(target) Release/obj.target/canvas/src/color.o
CXX(target) Release/obj.target/canvas/src/Image.o
CXX(target) Release/obj.target/canvas/src/ImageData.o
CXX(target) Release/obj.target/canvas/src/init.o
CXX(target) Release/obj.target/canvas/src/register_font.o
SOLINK_MODULE(target) Release/canvas.node
npm notice created a lockfile as package-lock.json. You should commit this file.
added 68 packages from 36 contributors in 18.261s
Script Output
mini:canv2-src jhuckaby$ node timing.js
#1 elapsed: 344.881935ms
#2 elapsed: 0.071105ms
Tests performed on Node.js v10.14.1, node-canvas v2.3.1 (Darwin darwin x64 18.2.0, 16384 MB RAM)
Another useful thing could be to time the entire process execution (time node ./test.js), in case those ~400 ms are being spent in initialization instead of the first instantiation of a canvas.
Actually, I thought about this when I wrote my test script. That's why I am specifically measuring only the createCanvas
and getContext
calls, and nothing else. You can see in my code I am calling process.hrtime() right before, then measuring the delta right after.
Another clue that might help: the delay seems to be in the call to getContext('2d')
. If I remove that, and just create a canvas without getting a context, there is no delay at all.
Thanks for the additional info! To summarize:
#1 Elapsed (ms) | OS | Version | Pango? | Pre/From Source | by |
---|---|---|---|---|---|
>300 | macOS | v2.3.1 | with | prebuilt | jh |
3 | macOS | v1.6.10 | without | from source | jh |
>300 | macOS | v1.6.11 | with | prebuilt | zb |
>300 | macOS | v2.3.1 | with | from source | jh |
(fast) | Linux | ... | |||
11 | Win10 | v2.3.1 | with | from source | zb |
10 | Win10 | v2.0.1 | with | prebuilt | zb |
Maybe pango requires tons of linking...
I thought about this when I wrote my test script. That's why I am specifically measuring only the createCanvas and getContext calls, and nothing else.
Yeah, my goal was to see if your fast v1.6 scenario (which I don't have a way to repro) was causing linking to happen before the first call to getContext
, and if v2.x allowed linking to not happen until getContext
. That should show up as similar total runtime between the fast and slow scenario. You might be able to see this directly if you add console.log()
statements before require("canvas")
, before createCanvas
, before getContext
and after getContext
, and run with DYLD_PRINT_LIBRARIES=1 DYLD_PRINT_BINDINGS=1 node ./test.js
. Then you can see when things are being loaded relative to each of your statements.
the delay seems to be in the call to getContext('2d')
That's when most of the real work is done; constructing a canvas does very little. This all still sounds like dyld being slow, but the big question is why it's not (apparently) slow in v1.6 built from source without pango.
Excellent summary table. To answer your with(?)
question on Pango for my v2.3.0 from-source macOS test, the answer is yes. Well, at least I'm assuming the answer is yes. I installed all the prerequisites including pango using brew, so I am assuming it compiled it in.
DYLD_PRINT_LIBRARIES=1 DYLD_PRINT_BINDINGS=1 node ./test.js
Wow, that's quite a verbose output! It is so long that I don't want to paste it all here, but I uploaded it as a text file to my S3 bucket:
https://pixlcore.com/bugs/node-canvas-1.6.10-timing-dyld-bindings.txt
Here's the test script for v1.0 with the console.logs as you requested:
// node-canvas v1.x timing test
console.log("before require");
var Canvas = require('canvas');
var hrTimeToMilliseconds = function(start) {
var diff = process.hrtime( start );
var nano = diff[0] * 1e9 + diff[1];
return nano / (1000000000 / 1000);
};
for (var idx = 1; idx <= 2; idx++) {
var start = process.hrtime();
console.log("idx " + idx + " before constructor");
var canvas = new Canvas( 1, 1 );
console.log("idx " + idx + " before getContext");
canvas.getContext('2d');
console.log("idx " + idx + " after getContext");
console.log( "#" + idx + " elapsed: " + hrTimeToMilliseconds(start) + "ms" );
}
const os = require('os');
console.log(
"Tests performed on Node.js " + process.version +
", node-canvas v" + require('canvas/package').version +
" (" + os.type() + " " + os.platform() + " " + os.arch() + " " +
os.release() + ", " + Math.floor( os.totalmem() / 1024 / 1024 ) + " MB RAM)"
);
Hope this helps!
That's perfect, thanks! I've posted the "slow" output for v1.6.11 below.
Distilled down:
fast | slow |
---|---|
require [422 loads/binds] idx 1 before constructor [17] idx 1 before getContext [7] idx 1 after getContext #1 elapsed: 0.781402ms idx 2 before constructor idx 2 before getContext idx 2 after getContext #2 elapsed: 0.143809ms |
require [1002 loads/binds] idx 1 before constructor [17] idx 1 before getContext [112] idx 1 after getContext [3] #1 elapsed: 455.573823ms idx 2 before constructor idx 2 before getContext idx 2 after getContext #2 elapsed: 0.198583ms |
During the getContext
call, the slow version has a lot of lazy pango bindings. I think that's the culprit, and makes sense given that the only fast case is the one you built without pango (whereas both v1 and v2 with pango are slow).
If we consider this a bug, a hack fix would be to force eager binding, which would make the require
call slow (idk if that's worse or better). But dyld shouldn't take 10-100x longer than the windows and ubuntu linkers in the first place... 🤔 Static linking would be another (complicated) work-around, at the expense of a larger binary.
I'll stop speculating now and hope someone who knows more about macOS/darwin can give some suggestions. I could be completely off-base!
Awesome, thank you for all this work! I agree this looks and feels like Pango.
This bug definitely isn't a show-stopper, as the library works great. It's only a bit unfortunate for use cases like a CLI image processor script, where it spawns a Node.js process for one single image operation, then exits and opens another one for the next image. In those cases we suffer that 500ms delay for each command -- but again, only on macOS.
I'll be running all my production code on Linux anyway, so this won't be a huge problem for me, haha.
Thanks again!
I think I ran into this problem as well and have found that setting the envvar
PANGOCAIRO_BACKEND="fc"
fixes things. However, my use case did not include font rendering, so I have not tested for differences in text quality at all.
This suggests that the issue lies in the pango/cairo coretext backend.
I just encountered this issue on Windows 10 with node-canvas v2.11.2 (installed through npm). About 300ms delay when getting the first context.
Hey guys, thanks for releasing node-canvas v2! Congrats on that.
On macOS (both 10.12 Sierra and 10.14 Mojave) with node-canvas v2.3.1, there is a strange 300 - 500 millisecond lag when creating the first canvas, no matter the resolution. Observe:
macOS 10.12 Sierra
macOS 10.14 Mojave
Steps to Reproduce
Here is the code to produce the above output:
As you can see I'm simply creating a 1x1 pixel canvas and grabbing a 2D context. I am using the Node.js high-resolution timer system to measure the createCanvas operation. The first canvas created is quite slow, where subsequent canvases in the same process are extremely fast.
This bug is not reproducible using the node-canvas 1.x branch, as you can see here:
Nor is it reproducible in Linux, regardless of node-canvas version. This appears to be a macOS + node-canvas v2.x performance issue.
Your Environment
Shown above as part of test script output.