Precise currently too slow to use on raspberry pi

Help
1

I know, I have been one of the guys championing for more use of precise - however, I am starting to doubt my own ambitions here.

Initially precise with “hey mycroft” kind of worked on my raspberry pi satellites, but recently it takes often up to 5s after uttering hey mycroft to get the beep of wkaeword detected - I am not sure what is going on here.

I recall precise in picroft being multitudes faster.

Does anybody have a better experience with precise on the raspberry pi as wakeword listener? Anybody having an idea what could be optimized?

It turns actually out that it gets often faster after running for a while.

Here is trace for the first recognition (which is often the slowest and takes 7s here):

[DEBUG:2020-06-16 11:24:57,103] rhasspywake_precise_hermes: Connecting to localhost:12183
1592317497: New connection from ::1 on port 12183.
1592317497: New client connected from ::1 as fd7d92c4-1ed7-4cb7-9396-e0281d15a1f7 (c1, k60).
[DEBUG:2020-06-16 11:24:57,140] rhasspywake_precise_hermes: Connected to MQTT broker
[DEBUG:2020-06-16 11:24:57,153] asyncio: Using selector: EpollSelector
[DEBUG:2020-06-16 11:24:57,144] rhasspywake_precise_hermes: Subscribed to rhasspy/hotword/getHotwords
[DEBUG:2020-06-16 11:24:57,159] rhasspywake_precise_hermes: Subscribed to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:24:57,161] rhasspywake_precise_hermes: Subscribed to hermes/audioServer/raspad/audioFrame
[DEBUG:2020-06-16 11:24:57,165] rhasspywake_precise_hermes: Subscribed to hermes/hotword/toggleOff
[DEBUG:2020-06-16 11:25:04,051] rhasspywake_precise_hermes: -> HotwordDetected(model_id='hey-mycroft-2.pb', model_version='', model_type='personal', current_sensitivity=0.5, site_id='raspad', session_id=None, send_audio_captured=None, lang=None)
[DEBUG:2020-06-16 11:25:04,052] rhasspywake_precise_hermes: Publishing 183 bytes(s) to hermes/hotword/hey-mycroft-2/detected
[DEBUG:2020-06-16 11:25:04,067] rhasspyserver_hermes: <- HotwordDetected(model_id='hey-mycroft-2.pb', model_version='', model_type='personal', current_sensitivity=0.5, site_id='raspad', session_id=None, send_audio_captured=None, lang=None)
[DEBUG:2020-06-16 11:25:04,070] rhasspydialogue_hermes: <- HotwordDetected(model_id='hey-mycroft-2.pb', model_version='', model_type='personal', current_sensitivity=0.5, site_id='raspad', session_id=None, send_audio_captured=None, lang=None)
[DEBUG:2020-06-16 11:25:04,073] rhasspydialogue_hermes: Playing WAV /home/pi/rhasspy/etc/wav/beep_hi.wav
[DEBUG:2020-06-16 11:25:04,079] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:04,080] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-06-16 11:25:04,090] rhasspydialogue_hermes: -> AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:04,092] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOff
[DEBUG:2020-06-16 11:25:04,096] rhasspywake_precise_hermes: <- HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:04,098] rhasspywake_precise_hermes: Disabled
[DEBUG:2020-06-16 11:25:04,099] rhasspydialogue_hermes: -> AudioPlayBytes(83948 byte(s))
[DEBUG:2020-06-16 11:25:04,114] rhasspyspeakers_cli_hermes: <- AudioPlayBytes(83948 byte(s))
[DEBUG:2020-06-16 11:25:04,126] rhasspydialogue_hermes: Waiting for playFinished (timeout=1.2012925170068027)
[DEBUG:2020-06-16 11:25:04,115] rhasspyasr_kaldi_hermes: <- AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:04,118] rhasspyasr_kaldi_hermes: Disabled (AsrToggleReason.PLAY_AUDIO)
[DEBUG:2020-06-16 11:25:04,118] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'default']
[WARNING:2020-06-16 11:25:05,333] rhasspydialogue_hermes: Did not receive sayFinished before timeout
[DEBUG:2020-06-16 11:25:05,340] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:05,341] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:25:05,346] rhasspydialogue_hermes: -> AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:05,347] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOn
[DEBUG:2020-06-16 11:25:05,349] rhasspydialogue_hermes: Starting new session (id=raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08)
[DEBUG:2020-06-16 11:25:05,354] rhasspydialogue_hermes: -> DialogueSessionStarted(session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', site_id='raspad', custom_data='hey-mycroft-2', lang=None)
[DEBUG:2020-06-16 11:25:05,356] rhasspydialogue_hermes: Publishing 139 bytes(s) to hermes/dialogueManager/sessionStarted
[DEBUG:2020-06-16 11:25:05,362] rhasspywake_precise_hermes: <- HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:05,365] rhasspywake_precise_hermes: Enabled
[DEBUG:2020-06-16 11:25:05,365] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:05,367] rhasspydialogue_hermes: Publishing 49 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-06-16 11:25:05,365] rhasspyasr_kaldi_hermes: <- AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:05,368] rhasspyasr_kaldi_hermes: Enabled
[DEBUG:2020-06-16 11:25:05,370] rhasspydialogue_hermes: Listening for session raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08
[DEBUG:2020-06-16 11:25:05,377] rhasspywake_precise_hermes: <- HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:05,380] rhasspydialogue_hermes: -> AsrStartListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', lang=None, stop_on_silence=True, send_audio_captured=True, wakeword_id='hey-mycroft-2', intent_filter=None)
[DEBUG:2020-06-16 11:25:05,378] rhasspywake_precise_hermes: Receiving audio
[DEBUG:2020-06-16 11:25:05,379] rhasspywake_precise_hermes: Disabled
[DEBUG:2020-06-16 11:25:05,382] rhasspydialogue_hermes: Publishing 211 bytes(s) to hermes/asr/startListening
[DEBUG:2020-06-16 11:25:05,400] rhasspyasr_kaldi_hermes: <- AsrStartListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', lang=None, stop_on_silence=True, send_audio_captured=True, wakeword_id='hey-mycroft-2', intent_filter=None)
[DEBUG:2020-06-16 11:25:05,402] rhasspyasr_kaldi_hermes: Creating new transcriber session raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08
[DEBUG:2020-06-16 11:25:05,403] rhasspymicrophone_pyaudio_hermes: <- AsrStartListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', lang=None, stop_on_silence=True, send_audio_captured=True, wakeword_id='hey-mycroft-2', intent_filter=None)
[DEBUG:2020-06-16 11:25:05,406] rhasspymicrophone_pyaudio_hermes: Disable UDP output
[DEBUG:2020-06-16 11:25:05,413] rhasspyasr_kaldi.transcribe: Using kaldi at /home/pi/rhasspy/.venv/lib/kaldi
[DEBUG:2020-06-16 11:25:05,415] rhasspyasr_kaldi_hermes: Starting listening (session_id=raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08)
[DEBUG:2020-06-16 11:25:05,425] rhasspyasr_kaldi.transcribe: ['/home/pi/rhasspy/.venv/lib/kaldi/online2-tcp-nnet3-decode-faster', '--port-num=60507', '--config=/home/pi/.config/rhasspy/profiles/en/kaldi/model/online/conf/online.conf', '--frame-subsampling-factor=3', '--max-active=7000', '--lattice-beam=8.0', '--acoustic-scale=1.0', '--beam=24.0', '/home/pi/.config/rhasspy/profiles/en/kaldi/model/model/final.mdl', '/home/pi/.config/rhasspy/profiles/en/kaldi/model/graph/HCLG.fst', '/home/pi/.config/rhasspy/profiles/en/kaldi/model/graph/words.txt']
[DEBUG:2020-06-16 11:25:05,433] rhasspyasr_kaldi_hermes: Receiving audio
[DEBUG:2020-06-16 11:25:05,634] rhasspyasr_kaldi.transcribe: /home/pi/rhasspy/.venv/lib/kaldi/online2-tcp-nnet3-decode-faster --port-num=60507 --config=/home/pi/.config/rhasspy/profiles/en/kaldi/model/online/conf/online.conf --frame-subsampling-factor=3 --max-active=7000 --lattice-beam=8.0 --acoustic-scale=1.0 --beam=24.0 /home/pi/.config/rhasspy/profiles/en/kaldi/model/model/final.mdl /home/pi/.config/rhasspy/profiles/en/kaldi/model/graph/hclg.fst /home/pi/.config/rhasspy/profiles/en/kaldi/model/graph/words.txt
[DEBUG:2020-06-16 11:25:05,811] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:computederivedvars():ivector-extractor.cc:183) computing derived variables for ivector extractor
[DEBUG:2020-06-16 11:25:06,338] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='6cc75456-d24a-41b3-aa1d-57d6a88ab2b5', session_id='')
[DEBUG:2020-06-16 11:25:06,342] rhasspyspeakers_cli_hermes: Publishing 63 bytes(s) to hermes/audioServer/raspad/playFinished
[DEBUG:2020-06-16 11:25:06,357] rhasspydialogue_hermes: <- AudioPlayFinished(id='6cc75456-d24a-41b3-aa1d-57d6a88ab2b5', session_id='')
[DEBUG:2020-06-16 11:25:06,360] rhasspytts_cli_hermes: <- AudioPlayFinished(id='6cc75456-d24a-41b3-aa1d-57d6a88ab2b5', session_id='')
[DEBUG:2020-06-16 11:25:08,015] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:computederivedvars():ivector-extractor.cc:204) done.
[DEBUG:2020-06-16 11:25:08,324] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:removeorphannodes():nnet-nnet.cc:948) removed 1 orphan nodes.
[DEBUG:2020-06-16 11:25:08,325] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:removeorphancomponents():nnet-nnet.cc:847) removing 2 orphan components.
[DEBUG:2020-06-16 11:25:08,326] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:collapse():nnet-utils.cc:1472) added 1 components, removed 2
[DEBUG:2020-06-16 11:25:08,603] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:compilelooped():nnet-compile-looped.cc:345) spent 0.182972 seconds in looped compilation.
[DEBUG:2020-06-16 11:25:08,604] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:listen():online2-tcp-nnet3-decode-faster.cc:379) tcpserver: listening on port: 60507
[DEBUG:2020-06-16 11:25:08,605] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:accept():online2-tcp-nnet3-decode-faster.cc:393) waiting for client...
[DEBUG:2020-06-16 11:25:08,605] rhasspyasr_kaldi.transcribe: Decoder started
[DEBUG:2020-06-16 11:25:08,612] rhasspyasr_kaldi.transcribe: Finished stream. Getting transcription.
[DEBUG:2020-06-16 11:25:09,964] rhasspyasr_kaldi.transcribe: ['']
[DEBUG:2020-06-16 11:25:09,966] rhasspyasr_kaldi_hermes: Transcription result: None
[ERROR:2020-06-16 11:25:09,968] rhasspyasr_kaldi_hermes: session proc
Traceback (most recent call last):
  File "/home/pi/rhasspy/rhasspy-asr-kaldi-hermes/rhasspyasr_kaldi_hermes/__init__.py", line 266, in transcribe_proc
    ), "Null transcription"
AssertionError: Null transcription
[DEBUG:2020-06-16 11:25:10,025] rhasspyasr_kaldi_hermes: -> AsrTextCaptured(text='', likelihood=0, seconds=0, site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', wakeword_id=None, asr_tokens=None, lang=None)
[DEBUG:2020-06-16 11:25:10,026] rhasspyasr_kaldi_hermes: Publishing 190 bytes(s) to hermes/asr/textCaptured
[DEBUG:2020-06-16 11:25:10,038] rhasspydialogue_hermes: <- AsrTextCaptured(text='', likelihood=0, seconds=0, site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', wakeword_id=None, asr_tokens=None, lang=None)
[DEBUG:2020-06-16 11:25:10,041] rhasspyasr_kaldi_hermes: -> AsrAudioCaptured(35564 byte(s))
[DEBUG:2020-06-16 11:25:10,046] rhasspydialogue_hermes: Playing WAV /home/pi/rhasspy/etc/wav/beep_lo.wav
[DEBUG:2020-06-16 11:25:10,051] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:10,052] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-06-16 11:25:10,058] rhasspydialogue_hermes: -> AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:10,059] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOff
[DEBUG:2020-06-16 11:25:10,061] rhasspydialogue_hermes: -> AudioPlayBytes(119908 byte(s))
[DEBUG:2020-06-16 11:25:10,063] rhasspydialogue_hermes: Waiting for playFinished (timeout=1.6090022675736961)
[DEBUG:2020-06-16 11:25:10,077] rhasspyspeakers_cli_hermes: <- AudioPlayBytes(119908 byte(s))
[DEBUG:2020-06-16 11:25:10,079] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'default']
[DEBUG:2020-06-16 11:25:10,111] rhasspywake_precise_hermes: <- HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:10,117] rhasspywake_precise_hermes: Disabled
[DEBUG:2020-06-16 11:25:10,230] rhasspyasr_kaldi_hermes: <- AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:10,234] rhasspyasr_kaldi_hermes: Disabled (AsrToggleReason.PLAY_AUDIO)
[WARNING:2020-06-16 11:25:11,677] rhasspydialogue_hermes: Did not receive sayFinished before timeout
[DEBUG:2020-06-16 11:25:11,681] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,682] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:25:11,686] rhasspydialogue_hermes: -> AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,688] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOn
[DEBUG:2020-06-16 11:25:11,689] rhasspydialogue_hermes: Received text: 
[DEBUG:2020-06-16 11:25:11,693] rhasspydialogue_hermes: -> AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,695] rhasspydialogue_hermes: Publishing 94 bytes(s) to hermes/asr/stopListening
[DEBUG:2020-06-16 11:25:11,701] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:11,702] rhasspydialogue_hermes: Publishing 49 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:25:11,707] rhasspydialogue_hermes: -> NluQuery(input='', site_id='raspad', id=None, intent_filter=None, session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', wakeword_id='hey-mycroft-2', lang=None)
[DEBUG:2020-06-16 11:25:11,708] rhasspywake_precise_hermes: <- HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,709] rhasspywake_precise_hermes: Still disabled: {<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>}
[DEBUG:2020-06-16 11:25:11,709] rhasspydialogue_hermes: Publishing 186 bytes(s) to hermes/nlu/query
[DEBUG:2020-06-16 11:25:11,714] rhasspyasr_kaldi_hermes: <- AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,716] rhasspyasr_kaldi_hermes: Enabled
[DEBUG:2020-06-16 11:25:11,719] rhasspymicrophone_pyaudio_hermes: <- AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,721] rhasspymicrophone_pyaudio_hermes: Enable UDP output
[DEBUG:2020-06-16 11:25:11,725] rhasspywake_precise_hermes: <- HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:11,730] rhasspyasr_kaldi_hermes: <- AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,733] rhasspyasr_kaldi_hermes: Stopping listening (session_id=raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08)
[DEBUG:2020-06-16 11:25:11,736] rhasspywake_precise_hermes: Receiving audio
[DEBUG:2020-06-16 11:25:11,742] rhasspywake_precise_hermes: Enabled
[DEBUG:2020-06-16 11:25:11,742] rhasspynlu_hermes: <- NluQuery(input='', site_id='raspad', id=None, intent_filter=None, session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', wakeword_id='hey-mycroft-2', lang=None)
[DEBUG:2020-06-16 11:25:11,748] rhasspynlu_hermes: Loading /home/pi/.config/rhasspy/profiles/en/intent_graph.pickle.gz
[DEBUG:2020-06-16 11:25:11,945] rhasspynlu_hermes: -> NluIntentNotRecognized(input='', site_id='raspad', id=None, custom_data=None, session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,948] rhasspynlu_hermes: Publishing 139 bytes(s) to hermes/nlu/intentNotRecognized
[DEBUG:2020-06-16 11:25:11,958] rhasspyserver_hermes: <- NluIntentNotRecognized(input='', site_id='raspad', id=None, custom_data=None, session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,958] rhasspydialogue_hermes: <- NluIntentNotRecognized(input='', site_id='raspad', id=None, custom_data=None, session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:11,963] rhasspydialogue_hermes: Playing WAV /home/pi/rhasspy/etc/wav/beep_error.wav
[DEBUG:2020-06-16 11:25:11,981] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,982] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-06-16 11:25:11,995] rhasspywake_precise_hermes: <- HotwordToggleOff(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:11,996] rhasspywake_precise_hermes: Disabled
[DEBUG:2020-06-16 11:25:11,997] rhasspydialogue_hermes: -> AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:12,000] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOff
[DEBUG:2020-06-16 11:25:12,003] rhasspydialogue_hermes: -> AudioPlayBytes(155492 byte(s))
[DEBUG:2020-06-16 11:25:12,008] rhasspydialogue_hermes: Waiting for playFinished (timeout=2.012448979591837)
[DEBUG:2020-06-16 11:25:12,019] rhasspyasr_kaldi_hermes: <- AsrToggleOff(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:12,020] rhasspyasr_kaldi_hermes: Disabled (AsrToggleReason.PLAY_AUDIO)
[DEBUG:2020-06-16 11:25:12,565] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='98c738e9-b388-4d5f-bde4-c7b86040fcdd', session_id='')
[DEBUG:2020-06-16 11:25:12,566] rhasspyspeakers_cli_hermes: Publishing 63 bytes(s) to hermes/audioServer/raspad/playFinished
[DEBUG:2020-06-16 11:25:12,570] rhasspyspeakers_cli_hermes: <- AudioPlayBytes(155492 byte(s))
[DEBUG:2020-06-16 11:25:12,572] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'default']
[DEBUG:2020-06-16 11:25:12,580] rhasspytts_cli_hermes: <- AudioPlayFinished(id='98c738e9-b388-4d5f-bde4-c7b86040fcdd', session_id='')
[DEBUG:2020-06-16 11:25:12,583] rhasspydialogue_hermes: <- AudioPlayFinished(id='98c738e9-b388-4d5f-bde4-c7b86040fcdd', session_id='')
[WARNING:2020-06-16 11:25:14,025] rhasspydialogue_hermes: Did not receive sayFinished before timeout
[DEBUG:2020-06-16 11:25:14,030] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:14,030] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:25:14,036] rhasspydialogue_hermes: -> AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:14,037] rhasspydialogue_hermes: Publishing 43 bytes(s) to hermes/asr/toggleOn
[WARNING:2020-06-16 11:25:14,039] rhasspydialogue_hermes: No intent recognized (session_id=raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08)
[DEBUG:2020-06-16 11:25:14,044] rhasspydialogue_hermes: -> AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:14,045] rhasspydialogue_hermes: Publishing 94 bytes(s) to hermes/asr/stopListening
[DEBUG:2020-06-16 11:25:14,055] rhasspywake_precise_hermes: <- HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:14,056] rhasspywake_precise_hermes: Enabled
[DEBUG:2020-06-16 11:25:14,057] rhasspydialogue_hermes: -> DialogueSessionEnded(termination=DialogueSessionTermination(reason=<DialogueSessionTerminationReason.INTENT_NOT_RECOGNIZED: 'intentNotRecognized'>), session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08', site_id='raspad', custom_data='hey-mycroft-2')
[DEBUG:2020-06-16 11:25:14,060] rhasspydialogue_hermes: Publishing 175 bytes(s) to hermes/dialogueManager/sessionEnded
[DEBUG:2020-06-16 11:25:14,060] rhasspyasr_kaldi_hermes: <- AsrToggleOn(site_id='raspad', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-06-16 11:25:14,062] rhasspyasr_kaldi_hermes: Enabled
[DEBUG:2020-06-16 11:25:14,068] rhasspyasr_kaldi_hermes: <- AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:14,066] rhasspymicrophone_pyaudio_hermes: <- AsrStopListening(site_id='raspad', session_id='raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08')
[DEBUG:2020-06-16 11:25:14,067] rhasspymicrophone_pyaudio_hermes: Enable UDP output
[DEBUG:2020-06-16 11:25:14,069] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:14,070] rhasspydialogue_hermes: Publishing 49 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-06-16 11:25:14,069] rhasspyasr_kaldi_hermes: Stopping listening (session_id=raspad-hey-mycroft-2-db780d34-e3e6-43e0-bd7e-f8f6708fad08)
[DEBUG:2020-06-16 11:25:14,078] rhasspywake_precise_hermes: <- HotwordToggleOn(site_id='raspad', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-06-16 11:25:14,079] rhasspywake_precise_hermes: Enabled
[DEBUG:2020-06-16 11:25:14,099] rhasspywake_precise_hermes: Receiving audio
2

Precise is using TensorFlow, right? I have seen the same behaviour in other code using TensorFlow. The first inference is always slower because the system then initializes various resources.

3

I use it from voice2json. There is a start up period that can be up to 30s on a pi 3 and around 15s on pi 4. After this start up it pretty much instantaneous for me. The delay is just if i speak the wake word in that start up period. At least in voice2json it looks like the audio stream is already started right away and than precise clears the buffer when started up and any detection of the wake word spoken in that period will occur delayed.

4

@koan yes it does use tensorflow and the startup theory seems sound, first time is slow, second and third is fast - wonder if the first time can somehow be triggered manually.

@JGKK, guess I need to get into voice2json quickly - I have trouble understanding what is all going on in rhasspy, there is imho too much mqtt network traffic going on that doesn’t seem very light and out of my control
maybe my satellites voice recognition setup becomes easier to handle with voice2json

5

Well if you have any experience with nodered we are nearly ready to do an open beta with an integration of voice2json for nodered which should it make really easy to use. Pretty much install voice2json and the corresponding nodes, download a profile and from there on you can use it purely from nodered.
You can look at the progress here (right now its missing a lot of documentation but the nodes are all functional):


I already used the current state to bootstrap a whole assistant based on nodered and voice2json including satellites and hotword coalescing stuff.
I set up a simple assistant in like ten minutes end to end including installation.
1 Like
6

Now, I remember where I read your name :wink:

Yes, I use and teach a lot node-red. My home automation is based on node-red, rhasspy, mycroft, and my own IoT framework IoTempower for programming esp8266-based devices.

7

I share the same concerns as @ulno regarding precise performance.

After applying the process described in this thread on my PI3B+, I observed CPU load close to 100% which is not acceptable to me.

Then I reverted my Rhasspy setup to snowboy and started using precise-listen to make sure that Rhasspy is not introducing overhead. Unfortunately this gives the same results with desperating high load (when snowboy runs very well in 10-15% range) :frowning:

I may open an issue in precise github in order to get more support…

8

I don’t think its tensorflow as in a vanilla model but prob something like the scorer that deepspeech employs causes delays.

Precise isn’t the fasest or lightest tensorflow implementation I have seen from running Mycroft on a Pi3.
With example code and simple vanilla tensorflow models I have played with I haven’t noticed a first start delay and never progressed advanced enough to find out what methods like the deepspeech scorer do.

As far as I am aware Precise has always been that way and the minimum recommended spec is Pi3, it is partly what put me off Mycroft even though ‘open source’.

Maybe its because most of my tests have been using my PC due to also creating the models and the delay isn’t discernible there, but precise definately causes quite a bit of load on all cores.
I think sonopy adds quite a bit to the load.

Not really a fan of Precise and still in search of a good opensource KWS.

9

Hmm this is what i see on average with precise on a pi 3b+

image
image1125×347 149 KB

This is with voice2json not rhasspy but that shouldn’t make a huge difference. Precise is beeing fed with audio from sox both connected over nodered.
As soon as the start up period is over it reacts with very little to no delay.

10

yep, I think not only precise is the problem here - I will take a look at voice2json - just don’t have the time at the moment - spent too much time fixing and guessing about issues in rhasspy 2.5, should have headed directly to voice2json probably

11

But it shouldn’t make such a big difference as voice2json is pretty much build on rhasspys technical foundations as i understand it. Just a little bit less overhead.

12

On my side I have the following usually in the 75-90% range:

top
top961×282 22.8 KB

@JGKK what’s the size of your .pb file? For me it’s 27K

13

Well if the cpu has 4 cores 90% is actually something like 24% per core as the 100 is not absolute over all cores that you see in top or htop but the scale corresponds to one core which can be confusing as it can go to 400% load in theory. On a pi3 i see 50-70% and on a pi 4 40-60%. So on a pi 3 which has 4 cores i would worry if it was at 200% or above.
70-90 percent in top are nothing to worry about if the pi has a good heatsink.