Closed cuongleqq closed 8 years ago
offshore
commented
8 years ago Try debug steps I suggest in #4245 -- it helps to determine if the problem is related to NW or your filesystem. Also, you are talking about VM, so at first you can just try unmounting your (virtual) CD drive.
cuongleqq
commented
8 years ago Hi, thank you for your response.
Firstly, my VM does not have any CD driver
Secondly, these are the results in 2 cases
index.html and package.jsonvagrant@vagrant-ubuntu-trusty:~/myusername/local-test$ strace -c ./nwjs-sdk-v0.13.0-beta4-linux-x64/nw test-nwjs0134
[0125/165256:INFO:nw_package.cc(175)] ./nwjs-sdk-v0.13.0-beta4-linux-x64/nw test-nwjs0134
[4293:4293:0125/165256:ERROR:browser_main_loop.cc(256)] Gtk: Locale not supported by C library.
Using the fallback 'C' locale.
Fontconfig warning: ignoring UTF-8: not a valid region tag
[4293:4293:0125/165258:ERROR:logging.h(808)] Failed to call method: org.freedesktop.DBus.ObjectManager.GetManagedObjects: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.bluez was not provided by any .service files
[4293:4293:0125/165258:ERROR:logging.h(808)] Failed to call method: org.freedesktop.DBus.ObjectManager.GetManagedObjects: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.bluez was not provided by any .service files
[4319:4319:0125/165259:ERROR:gl_implementation_osmesa.cc(22)] Failed to load libGL.so.1: libGL.so.1: cannot open shared object file: No such file or directory
[4319:4319:0125/165259:ERROR:gpu_child_thread.cc(257)] Exiting GPU process due to errors during initialization
[4293:4309:0125/165300:ERROR:browser_gpu_channel_host_factory.cc(132)] Failed to launch GPU process.
[4293:4309:0125/165300:ERROR:browser_gpu_channel_host_factory.cc(132)] Failed to launch GPU process.
^CProcess 4293 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
13.56 0.066363 46 1441 178 open
13.36 0.065390 30 2212 fstat
9.68 0.047381 36 1334 mmap
9.56 0.046775 32 1467 1 read
8.22 0.040238 30 1354 close
7.99 0.039089 68 575 poll
7.10 0.034754 31 1123 1036 openat
6.49 0.031781 29 1079 munmap
6.45 0.031565 22 1449 1267 recvmsg
5.54 0.027137 26 1038 lseek
2.85 0.013925 76 184 mprotect
2.00 0.009773 56 176 104 access
1.88 0.009195 43 215 write
1.40 0.006861 22 306 3 futex
0.95 0.004674 24 195 writev
0.89 0.004354 34 129 madvise
0.52 0.002564 26 100 26 stat
0.46 0.002264 25 91 getdents
0.27 0.001312 42 31 rt_sigaction
0.10 0.000468 117 4 rt_sigprocmask
0.09 0.000458 57 8 fstatfs
0.09 0.000432 14 32 8 lstat
0.06 0.000315 32 10 6 readlink
0.05 0.000231 7 34 uname
0.04 0.000216 72 3 2 statfs
0.04 0.000202 67 3 bind
0.04 0.000173 87 2 1 setpriority
0.03 0.000163 163 1 wait4
0.03 0.000161 161 1 fadvise64
0.03 0.000160 13 12 socket
0.03 0.000148 2 97 gettid
0.02 0.000107 21 5 sendmsg
0.02 0.000106 5 21 fcntl
0.02 0.000091 9 10 sendto
0.02 0.000074 74 1 sched_getparam
0.01 0.000071 71 1 execve
0.01 0.000069 35 2 getpriority
0.01 0.000068 68 1 set_tid_address
0.01 0.000067 67 1 sched_getscheduler
0.01 0.000067 67 1 set_robust_list
0.01 0.000066 17 4 getrlimit
0.01 0.000062 62 1 arch_prctl
0.01 0.000060 60 1 brk
0.00 0.000000 0 1 rt_sigreturn
0.00 0.000000 0 4 pipe
0.00 0.000000 0 3 dup
0.00 0.000000 0 8 2 connect
0.00 0.000000 0 7 2 recvfrom
0.00 0.000000 0 2 shutdown
0.00 0.000000 0 1 listen
0.00 0.000000 0 8 getsockname
0.00 0.000000 0 2 getpeername
0.00 0.000000 0 4 socketpair
0.00 0.000000 0 5 setsockopt
0.00 0.000000 0 20 clone
0.00 0.000000 0 1 ftruncate
0.00 0.000000 0 5 getcwd
0.00 0.000000 0 2 mkdir
0.00 0.000000 0 1 creat
0.00 0.000000 0 3 2 unlink
0.00 0.000000 0 4 symlink
0.00 0.000000 0 1 getuid
0.00 0.000000 0 2 getresuid
0.00 0.000000 0 2 getresgid
0.00 0.000000 0 2 sigaltstack
0.00 0.000000 0 1 setrlimit
0.00 0.000000 0 1 clock_getres
0.00 0.000000 0 1 eventfd2
------ ----------- ----------- --------- --------- ----------------
100.00 0.489430 14846 2638 totalindex.html, package.json and node_modules folder with a lot of files in itvagrant@vagrant-ubuntu-trusty:~/myusername/local-test$ strace -c ./nwjs-sdk-v0.13.0-beta4-linux-x64/nw test-nwjs0134
[0125/164922:INFO:nw_package.cc(175)] ./nwjs-sdk-v0.13.0-beta4-linux-x64/nw test-nwjs0134
[4239:4239:0125/164922:ERROR:browser_main_loop.cc(256)] Gtk: Locale not supported by C library.
Using the fallback 'C' locale.
Fontconfig warning: ignoring UTF-8: not a valid region tag
[4239:4239:0125/164923:ERROR:logging.h(808)] Failed to call method: org.freedesktop.DBus.ObjectManager.GetManagedObjects: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.bluez was not provided by any .service files
[4265:4265:0125/164925:ERROR:gl_implementation_osmesa.cc(22)] Failed to load libGL.so.1: libGL.so.1: cannot open shared object file: No such file or directory
[4265:4265:0125/164925:ERROR:gpu_child_thread.cc(257)] Exiting GPU process due to errors during initialization
[4239:4239:0125/165140:ERROR:logging.h(808)] Failed to call method: org.freedesktop.DBus.ObjectManager.GetManagedObjects: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.bluez was not provided by any .service files
[4239:4255:0125/165142:ERROR:browser_gpu_channel_host_factory.cc(132)] Failed to launch GPU process.
[4239:4255:0125/165142:ERROR:browser_gpu_channel_host_factory.cc(132)] Failed to launch GPU process.
^CProcess 4239 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
80.10 25.008001 298 83980 43 stat
15.48 4.831977 404 11961 1036 openat
1.38 0.430019 20 21767 getdents
1.06 0.330634 27 12199 close
1.03 0.321333 29 11045 madvise
0.18 0.054864 38 1449 183 open
0.12 0.037836 26 1468 1287 recvmsg
0.12 0.036860 24 1518 1 read
0.10 0.031461 14 2216 fstat
0.10 0.030672 23 1339 mmap
0.06 0.019922 34 585 poll
0.05 0.016245 15 1083 munmap
0.04 0.013045 13 1036 lseek
0.03 0.010271 56 183 118 access
0.03 0.009009 46 195 writev
0.03 0.008626 47 184 mprotect
0.03 0.007988 24 333 3 futex
0.02 0.007656 32 240 write
0.01 0.003186 100 32 8 lstat
0.01 0.002426 24 101 gettid
0.00 0.000878 110 8 fstatfs
0.00 0.000690 86 8 2 connect
0.00 0.000652 54 12 socket
0.00 0.000649 162 4 pipe
0.00 0.000625 63 10 6 readlink
0.00 0.000571 29 20 clone
0.00 0.000501 16 31 rt_sigaction
0.00 0.000466 155 3 creat
0.00 0.000364 46 8 getsockname
0.00 0.000279 8 34 uname
0.00 0.000232 33 7 2 recvfrom
0.00 0.000230 23 10 sendto
0.00 0.000219 219 1 wait4
0.00 0.000191 191 1 execve
0.00 0.000153 38 4 rt_sigprocmask
0.00 0.000151 38 4 getrlimit
0.00 0.000128 26 5 setsockopt
0.00 0.000116 39 3 bind
0.00 0.000104 104 1 setrlimit
0.00 0.000099 20 5 getcwd
0.00 0.000092 92 1 brk
0.00 0.000073 73 1 fadvise64
0.00 0.000062 62 1 arch_prctl
0.00 0.000009 5 2 rt_sigreturn
0.00 0.000000 0 4 dup
0.00 0.000000 0 5 sendmsg
0.00 0.000000 0 2 shutdown
0.00 0.000000 0 1 listen
0.00 0.000000 0 2 getpeername
0.00 0.000000 0 4 socketpair
0.00 0.000000 0 23 fcntl
0.00 0.000000 0 2 ftruncate
0.00 0.000000 0 5 mkdir
0.00 0.000000 0 4 2 unlink
0.00 0.000000 0 4 symlink
0.00 0.000000 0 1 getuid
0.00 0.000000 0 2 getresuid
0.00 0.000000 0 2 getresgid
0.00 0.000000 0 2 sigaltstack
0.00 0.000000 0 3 2 statfs
0.00 0.000000 0 2 getpriority
0.00 0.000000 0 2 1 setpriority
0.00 0.000000 0 1 sched_getparam
0.00 0.000000 0 1 sched_getscheduler
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 clock_getres
0.00 0.000000 0 1 set_robust_list
0.00 0.000000 0 1 eventfd2
------ ----------- ----------- --------- --------- ----------------
100.00 31.219565 153174 2694 totalBest regards,
offshore
commented
8 years ago As you can see, in second case 80% time is wasted on stat call, which is used to get filesystem info (captain Obvious to rescue :)). It means that it is your filesystem problem, it's waiting for something synchroniously. Try inspecting your mounts, and try moving your project somewhere (e.g. to /tmp, which normally doesn't have any subtree mounts) and launch from there.
I'm still sure it's about your FS, not NW.
Finally, to find out which call to stat results in time waste, use strace -T -e trace=stat path/to/nw path/to/app. You'll see the file being stat'ed and time spent on that.
rogerwang
commented
8 years ago Thanks for reporting. Could you please upload a sample?
cuongleqq
commented
8 years ago @offshore I moved to /tmp and it is much faster. The folder I was running the sample was the shared folder between the VM and host machine (I edit the code on host machine and install + run the nwjs app through the VM). I also tried strace -T -e trace=stat path/to/nw path/to/app and saw that stat run on all files in the path/to/app. So, I guess the stat runs on shared folder was slower than stat runs on /tmp folder and, there are too many files, making it even slower. My questions are:
stat for all the files in the folder even I do not require the modules in my project?
I really need the code in the shared folder (so that I can use sublime to edit files in the source folder from the host).@rogerwang We can reproduce this easily by putting the index.html and package.json in a folder which has many files. In my case, I just do npm install with these dependencies.
"devDependencies": {
"async": "^1.4.2",
"del": "^1.2.1",
"grunt": "^0.4.5",
"grunt-angular-templates": "^0.5.7",
"grunt-browser-output": "^1.0.3",
"grunt-contrib-clean": "^0.6.0",
"grunt-contrib-compress": "^0.13.0",
"grunt-contrib-concat": "^0.5.1",
"grunt-contrib-connect": "^0.10.1",
"grunt-contrib-copy": "^0.8.0",
"grunt-contrib-cssmin": "^0.12.3",
"grunt-contrib-htmlmin": "^0.4.0",
"grunt-contrib-jshint": "^0.11.2",
"grunt-contrib-less": "^1.0.1",
"grunt-contrib-uglify": "^0.9.1",
"grunt-contrib-watch": "^0.6.1",
"grunt-dom-munger": "^3.4.0",
"grunt-karma": "^0.11.0",
"grunt-newer": "^1.1.0",
"grunt-ng-annotate": "^1.0.1",
"grunt-nw-builder": "^2.0.0",
"grunt-protractor-runner": "^2.0.0",
"grunt-shell-spawn": "^0.3.8",
"jasmine-core": "^2.3.4",
"jit-grunt": "^0.9.1",
"karma": "^0.12.36",
"karma-jasmine": "^0.3.5",
"karma-mocha-reporter": "^1.0.2",
"load-grunt-tasks": "^3.2.0",
"nw": "^0.12.3"
},
"dependencies": {
"bigi": "^1.4.0",
"crypto-js": "^3.1.4",
"ncp": "^2.0.0",
"node-uuid": "^1.4.3",
"winston": "^1.0.0"
}On the shared folder of the VM, putting only one node_modules under the app folder is enough to make it slow. On the host (Mac with ssd), to make it slow, we can just duplicate the node_modules folder several times and then we can see the different in bootstrap time.
The sample is about 1Gb, the sample to make my Mac slow is about 12Gb (I haven't tried compressing them yet). Is it ok for you to download?
Thanks!
offshore
commented
8 years ago @cuongle121 maybe it's better to use network mounts or something?.. I'm afraid vm shared folders are not optimized for that (it's totally sync and have no cache inside; each fs access travels though sandboxing; etc). I'm not sure if it's Chromium or NW recursively scans for app files without digging some code; maybe the former does it to build local page cache or the latter does it for some reasons. If you are experiencing it in 0.13, but not in 0.12, it may be due to architecture changes. Well, I can keep pointless guessing, but for now to help you I can only suggest use another type of mount for your purpose.
rogerwang
commented
8 years ago @cuongle121 Chromium checks for illegal filenames when loading app: https://github.com/nwjs/chromium.src/blob/nw13/extensions/common/file_util.cc#L301
will disable this.
rogerwang
commented
8 years ago fixed in chromium repo and will be available in the next nightly build.
Hi,
I have been developing my project with nwjs 0.12.3 in a Linux VM recently. Although the VM is not as powerful as the host machine, the 0.12.3 version still runs very well. The bootstrap time is just 1 or 2 seconds. I am trying to switch to 0.13 beta 4, the bootstrap time (and also reloading time) for 0.13 beta 4 is about a minute.
I tried many set up and figured out that, if the folder I run the project has too many files (in my case, node_modules folder contains 33390 files including devDependencies), the bootstrap time would be very slow. I also tried the Mac version on my host machine (much more powerful than the VM), it is fast, though when I duplicated the node_modules to other 8 folders, it is slow down by about 5 seconds.
Please note that when I tried, I did not load anything in index.html, I only put some html tags and some text, no javascript was running in it.
So, basically, to reproduce this, you need a slow VM (I often use vagrant default VM setup), a simple package.json and index.html (no need to require any modules or run any javascript), a folderin the same level with index.html and contains lot of files in it (how big the file is does not matter).
Hope we can have a fix for this, I can not wait a minute to reload after I changed the code.
Thanks for reading (and sorry for my bad English)
Best Regards,