search

alphacep / vosk-api

Offline speech recognition API for Android, iOS, Raspberry Pi and servers with Python, Java, C# and Node
Apache License 2.0
7.48k stars 1.05k forks source link

VoskJS HTTPServer crash (v8::internal::GlobalBackingStoreRegistry::Register) #516

Open solyarisoftware opened 3 years ago

solyarisoftware commented 3 years ago

Hi Nicolay!

I'm working on VoskJs, a simple wrapper of nodejs Vosk binding, and I'm now released an HTTP server using last multi-threading features part of Vosk API. See: https://github.com/solyarisoftware/voskJs/blob/master/voskjs.js#L121

The draft HTTP server I implemented is very simple: it just takes HTTP POST /transcript requests, processing the speech file specified in the request body: https://github.com/solyarisoftware/voskJs/tree/master/examples#transcript-http-server

I want to stress test httpServer.js to monitor throughput and latencies, using an Apache Bench (ab) script: https://github.com/solyarisoftware/voskJs/blob/master/tests/abtest.sh

Running the ab stress test, with by example 2 concurrent requests (for 500 times), the server run smoothly for a while (100/200 requests), consuming almost 2 cores (see pidstat logs here listed), but the server crashes after a while. See here below the stderr messages. BTW, rising the number of concurrent requests, the server crashes in a minor time.

Reading error:

 3: 0x100c201 v8::internal::GlobalBackingStoreRegistry::Register(std::shared_ptr<v8::internal::BackingStore>) [node]

It seems to me that the issue could maybe related to some memory node binding problem.

Any idea? Please let me know if you need more info.

Thanks Giorgio

httpServer stderr

$ pidstat 1 -u -e node httpServer > httpServer.log

#
# Fatal error in , line 0
# Check failed: result.second.
#
#
#
#FailureMessage Object: 0x7ffcaa9487e0
 1: 0xb7db41  [node]
 2: 0x1c15474 V8_Fatal(char const*, ...) [node]
 3: 0x100c201 v8::internal::GlobalBackingStoreRegistry::Register(std::shared_ptr<v8::internal::BackingStore>) [node]
 4: 0xd23818 v8::ArrayBuffer::GetBackingStore() [node]
 5: 0xacb640 napi_get_typedarray_info [node]
 6: 0x7fb14c3a10ff  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 7: 0x7fb14c3a18a8  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 8: 0x7fb14c3a3591  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 9: 0x7fb14c3a9d6b Napi::details::CallbackData<void (*)(Napi::CallbackInfo const&), void>::Wrapper(napi_env__*, napi_callback_info__*) [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
10: 0xac220f  [node]
11: 0xd5f70b  [node]
12: 0xd60bac  [node]
13: 0xd61226 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [node]
14: 0x160c579  [node]

Apache Bench test 

$ com/abtest.sh 

test httpServer using apache bench
  2 concurrent clients
  500 requests to run

full ab command
  ab -p /home/giorgio/voskjs/examples/com/body.json -T application/json -H 'Content-Type: application/json' -c 2 -n 500 -l -k -r http://localhost:3000/transcript

This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Finished 500 requests

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /transcript
Document Length:        Variable

Concurrency Level:      2
Time taken for tests:   27.141 seconds
Complete requests:      500
Failed requests:        660
   (Connect: 0, Receive: 440, Length: 0, Exceptions: 220)
Keep-Alive requests:    0
Total transferred:      24973 bytes
Total body sent:        17080
HTML transferred:       18660 bytes
Requests per second:    18.42 [#/sec] (mean)
Time per request:       108.563 [ms] (mean)
Time per request:       54.282 [ms] (mean, across all concurrent requests)
Transfer rate:          0.90 [Kbytes/sec] received
                        0.61 kb/s sent
                        1.51 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     0  107 296.6      0    1214
Waiting:        0  103 288.8      0    1213
Total:          0  107 296.6      0    1214

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      0
  75%      0
  80%      0
  90%    739
  95%    981
  98%   1094
  99%   1174
 100%   1214 (longest request)

httpServer.log (excerpt)



Linux 5.8.0-50-generic (giorgio-HP-Laptop-17-by1xxx)  30/04/2021  _x86_64_  (8 CPU)
1619767436135 Press Ctrl-C to shutdown
1619767436136 Model directory: ../models/vosk-model-small-en-us-0.15
1619767436413 load model latency: 275ms
1619767436415 Server httpServer.js running at http://localhost:3000
1619767436415 Endpoint http://localhost:3000/transcript

09:23:55      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
09:23:56     1000     45074   46,00   10,00    0,00    0,00   56,00     7  node
09:23:57     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:23:58     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:23:59     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:24:00     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:24:01     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:24:02     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:24:03     1000     45074    0,00    0,00    0,00    0,00    0,00     7  node
09:24:04     1000     45074    2,00    0,00    0,00    0,00    2,00     7  node
1619767445908 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:05     1000     45074    8,00    0,00    0,00    0,00    8,00     7  node
1619767446466 id 1619767445908 transcript latency 558ms
1619767446466 response id 1619767445908 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767445908,"latency":558,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767446470 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767446526 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:06     1000     45074  139,00    2,00    0,00    0,00  141,00     7  node
1619767447189 id 1619767446470 transcript latency 719ms
1619767447189 response id 1619767446470 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767446470,"latency":719,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767447232 id 1619767446526 transcript latency 706ms
1619767447232 response id 1619767446526 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767446526,"latency":706,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767447233 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767447288 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767447954 id 1619767447288 transcript latency 666ms
1619767447954 response id 1619767447288 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767447288,"latency":666,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
09:24:07     1000     45074  176,00    0,00    0,00    0,00  176,00     7  node

1619767469520 id 1619767468466 transcript latency 1054ms
1619767469520 response id 1619767468466 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767468466,"latency":1054,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767469522 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:29     1000     45074  171,00    1,00    0,00    0,00  172,00     7  node
1619767470485 id 1619767469373 transcript latency 1111ms
1619767470485 response id 1619767469373 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767469373,"latency":1111,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767470546 id 1619767469522 transcript latency 1024ms
1619767470546 response id 1619767469522 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767469522,"latency":1024,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767470548 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767470635 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:30     1000     45074  174,00    0,00    0,00    0,00  174,00     7  node
1619767471542 id 1619767470635 transcript latency 906ms
1619767471542 response id 1619767470635 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767470635,"latency":906,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767471601 id 1619767470548 transcript latency 1053ms
1619767471601 response id 1619767470548 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767470548,"latency":1053,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767471604 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767471694 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:31     1000     45074  173,00    0,00    0,00    0,00  173,00     7  node
1619767472611 id 1619767471604 transcript latency 1007ms
1619767472611 response id 1619767471604 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767471604,"latency":1007,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767472672 id 1619767471694 transcript latency 978ms
1619767472672 response id 1619767471694 {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2","requestId":1619767471694,"latency":978,"result":[{"conf":1,"end":1.02,"start":0.36,"word":"experience"},{"conf":1,"end":1.35,"start":1.02,"word":"proves"},{"conf":1,"end":1.74,"start":1.35,"word":"this"}],"text":"experience proves this"}
1619767472674 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

1619767472764 request {"speech":"../audio/2830-3980-0043.wav","model":"vosk-model-en-us-aspire-0.2"}

09:24:32     1000     45074  149,00    1,00    0,00    0,00  150,00     0  node

Average:     1000     45074  127,76    0,73    0,00    0,00  128,49     -  node
nshmyrev commented 3 years ago

Looks like an issue with Node 14. What is your version?

https://github.com/node-ffi-napi/node-ffi-napi/issues/71

solyarisoftware commented 3 years ago

The latest:

$ node --version
v16.0.0
$ npm info vosk
vosk@0.3.25 | Apache-2.0 | deps: 4 | versions: 5
Node binding for continuous offline voice recoginition with Vosk library.
https://github.com/alphacep/vosk-api#readme

keywords: speech, speech recognition, voice

dist
.tarball: https://registry.npmjs.org/vosk/-/vosk-0.3.25.tgz
.shasum: 7e07549da96be439f7d49a59de60844a42fe421c
.integrity: sha512-9LTbW6E0QNP2RwgedIICKpQU+0EF3rf+3VT00NKVULJ0BGda84aMG0Mjc/Iv+05jyF7wghm42+Gw+s5vAUMpBA==
.unpackedSize: 77.6 MB

dependencies:
async: ^3.2.0     ffi-napi: ^4.0.3  ref-napi: >=2.0.0 wav: ^1.0.2       

maintainers:
- nshmyrev <nshmyrev@gmail.com>

dist-tags:
latest: 0.3.25  

published 4 days ago by nshmyrev <nshmyrev@gmail.com>

hmm...

nshmyrev commented 3 years ago

Also related

https://github.com/node-ffi-napi/ref-napi/issues/54

solyarisoftware commented 3 years ago

Thanks it's for me a bit difficult to follow the ref-napi open issues. I'll try to deepen.

BTW, I just updated the httpServer rerunning ab test, unfortunately I do not have good news. I also tryied to use less recent NodeJs v14.16.1 instead of v16.0.0 without success. Details in doc: https://github.com/solyarisoftware/voskJs/blob/master/tests/README.md#HTTP-Server-benchmark-test

solyarisoftware commented 3 years ago

Hi Nicolay

I'm following you tests on https://github.com/node-ffi-napi/ref-napi/issues/54 with some difficulties for my ignorance in these realms.

My side I done more trivial tests on my project VoskJS:

(1) if I do NOT use new Vosk multithreading feature, so I do NOT use rec.acceptWaveformAsync(data) but I use old (thread blocking) rec.acceptWaveform(data): https://github.com/solyarisoftware/voskJs/blob/master/voskjs.js#L137 I do not see the issue.

By example, consider a program that SEQUENTIALLY invokes Vosk API recognizer: https://github.com/solyarisoftware/voskJs/blob/master/tests/sequentialRequests.js#L27

If I use rec.acceptWaveform(data): 

const { result, latency } = await transcript(audioFile, model, {multiThreads:false})

All run smoothly and the there are no crashes.

(2) But the issue instead happens all times I use acceptWaveformAsync. By example in the program above if I set 

const { result, latency } = await transcript(audioFile, model, {multiThreads:true})

Now the program crashes after N requests: 

$ node sequentialRequests 500
requests               : 500

model directory        : ../models/vosk-model-small-en-us-0.15
speech file name       : ../audio/2830-3980-0043.wav

load model latency     : 327ms

request nr.            : 1
transcript latency     : 567ms
request nr.            : 2
transcript latency     : 583ms
request nr.            : 3
transcript latency     : 563ms
request nr.            : 4
transcript latency     : 553ms
request nr.            : 5
transcript latency     : 549ms
request nr.            : 6
transcript latency     : 561ms
request nr.            : 7
transcript latency     : 551ms
request nr.            : 8
transcript latency     : 571ms
request nr.            : 9
transcript latency     : 589ms
request nr.            : 10
transcript latency     : 560ms
request nr.            : 11
transcript latency     : 556ms
request nr.            : 12
transcript latency     : 557ms
request nr.            : 13
transcript latency     : 578ms
request nr.            : 14
transcript latency     : 563ms
request nr.            : 15
transcript latency     : 565ms
request nr.            : 16
transcript latency     : 571ms
request nr.            : 17
transcript latency     : 560ms
request nr.            : 18
transcript latency     : 595ms
request nr.            : 19
transcript latency     : 552ms

...
...

request nr.            : 71
transcript latency     : 781ms
request nr.            : 72
transcript latency     : 792ms
request nr.            : 73
transcript latency     : 774ms
request nr.            : 74
transcript latency     : 783ms
request nr.            : 75
transcript latency     : 791ms
request nr.            : 76
transcript latency     : 799ms
request nr.            : 77
transcript latency     : 799ms
request nr.            : 78
transcript latency     : 794ms
request nr.            : 79

#
# Fatal error in , line 0
# Check failed: result.second.
#
#
#
#FailureMessage Object: 0x7ffc02120c80
 1: 0xb7db41  [node]
 2: 0x1c15474 V8_Fatal(char const*, ...) [node]
 3: 0x100c201 v8::internal::GlobalBackingStoreRegistry::Register(std::shared_ptr<v8::internal::BackingStore>) [node]
 4: 0xd23818 v8::ArrayBuffer::GetBackingStore() [node]
 5: 0xacb640 napi_get_typedarray_info [node]
 6: 0x7f4554f3c0ff  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 7: 0x7f4554f3c8a8  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 8: 0x7f4554f3e591  [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
 9: 0x7f4554f44d6b Napi::details::CallbackData<void (*)(Napi::CallbackInfo const&), void>::Wrapper(napi_env__*, napi_callback_info__*) [/home/giorgio/voskjs/node_modules/ref-napi/prebuilds/linux-x64/node.napi.node]
10: 0xac220f  [node]
11: 0xd5f70b  [node]
12: 0xd60bac  [node]
13: 0xd61226 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [node]
14: 0x160c579  [node]
Illegal instruction (core dumped)

Note: it seems to me that N (after how much requests the crash happens) depends on the availability of free RAM. I mean that if I have "few" hundred MBs, just because I have the browser open etc., it seems that the program crashes after very few (N~=10) requests. Maybe this unrelated/I'm wrong. Just FYI

$ free -h
              total        used        free      shared  buff/cache   available
Mem:           11Gi       6,8Gi       1,6Gi       740Mi       3,3Gi       3,8Gi
Swap:         2,0Gi       1,8Gi       191Mi

Anyway, I believe you are one step in investigating the napi bug 54. I just wish to share with you my modest tests. Thanks Giorgio

nshmyrev commented 3 years ago

Its a work in progress. You can use node 13 for now, node 14-16 is broken. You have to wait till I fix this bug in node-ffi-napi.

solyarisoftware commented 3 years ago

Ah! I didn't try node 13 (but with node 16 and 14), good to know. thanks

solyarisoftware commented 3 years ago

Meanwhile, I confirm that with node 13.14.0, all tests I previous mentioned, pass successfully (without any crash) .

$ node --version
v13.14.0
$ cd examples
$ node httpServer --model=../models/vosk-model-small-en-us-0.15
$ cd tests
$ abtest.sh 

test httpServer using apache bench
  10 concurrent clients
  200 requests to run

full ab command
  ab -p /home/giorgio/voskjs/tests/body.json -T application/json -H 'Content-Type: application/json' -c 10 -n 200 -l -k -r http://localhost:3000/transcript

This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Finished 200 requests

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /transcript
Document Length:        Variable

Concurrency Level:      10
Time taken for tests:   78.491 seconds
Complete requests:      200
Failed requests:        0
Keep-Alive requests:    0
Total transferred:      78199 bytes
Total body sent:        48400
HTML transferred:       56799 bytes
Requests per second:    2.55 [#/sec] (mean)
Time per request:       3924.528 [ms] (mean)
Time per request:       392.453 [ms] (mean, across all concurrent requests)
Transfer rate:          0.97 [Kbytes/sec] received
                        0.60 kb/s sent
                        1.58 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   603 3836 628.8   4029    4808
Waiting:      601 3734 636.1   3955    4804
Total:        603 3836 628.8   4030    4808

Percentage of the requests served within a certain time (ms)
  50%   4030
  66%   4146
  75%   4221
  80%   4296
  90%   4487
  95%   4655
  98%   4737
  99%   4808
 100%   4808 (longest request)
AlexMisiulia commented 3 years ago

Hi! Any updates or plans for this issue? Thanks!

AlexMisiulia commented 3 years ago

@nshmyrev As I can see this issue is already fixed in node-ffi-napi4.x.

solyarisoftware commented 3 years ago

hi @AlexMisiulia why you state the issue is already fixed? I don't see any news from comments related to the issue you mentioned. I'm wrong?

AlexMisiulia commented 3 years ago

hi @solyarisoftware! I just had a quick look that issue is closed and was fixed in 3.x version. But now after closer look I can see that version 4.x has this bug. Maybe it is an option to update to the latest 3.x version. Downgrading nodejs to 13 is not a good option for me. I try to find minor workaround

nshmyrev commented 3 years ago

Maintainer is silent, you can ping her in https://github.com/node-ffi-napi/ref-napi/issues/54. For now looks like we have to fork the ffi-napi package though I'm not excited about it.

AlexMisiulia commented 3 years ago

@nshmyrev thanks for the response. I pinged her but I don't think that it will help because package is not actively supported.

AlexMisiulia commented 3 years ago

@nshmyrev no response from ref-napi developer and seems that this issue won't be fixed in the nearest future. Also I saw that library is not frequently updated (last release was on May 18). I swa that you have already made a fork with a fix. Maybe it won't be that painful to pack forked version or apply patches after building node-ffi-napi? What do you think? Thanks!

nab138 commented 2 years ago

Is there any more info on this? I'm having a similar issue