Jibri takes time to start recording

[LohithBlaze]

Hi,

We are deploying jibri in an aws instance and we found that jibri takes around 7-8 secs on t2.small and 4-5 secs on t2.large.

Do you know why jibri is taking so much time to start the recording? Is there anything to speed up the jibri processing.

[bbaldino]

Is this just the first time after the jibri instance boots? Or every time? If it's just the first time it boots, it's chrome being slow and it will help to "prime" it by starting chrome once at boot. If it's every time, attach logs.

[LohithBlaze]

2021-08-30 02:47:52.984 FINE: [1059] org.jitsi.xmpp.mucclient.MucClient.log() Received an IQ with type set: IQ Stanza (jibri http://jitsi.org/protocol/jibri) [to=jibri@auth.*************************/ZO-otokM,from=jibribrewery@*************************/focus,id=amlicmlAYXV0aC51bml0MDAxLm11bS5hcC1zb3V0aC0xLmRvbHBoaW52Yy5jb20vWk8tb3Rva00AN2wzODEtNzgzNjY2MADtv3VNFNVSgDXqfGM6K6C5,type=set,]
2021-08-30 02:47:52.985 INFO: [1059] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.*************************/ZO-otokM' from='jibribrewery@*************************/focus' id='amlicmlAYXV0aC51bml0MDAxLm11bS5hcC1zb3V0aC0xLmRvbHBoaW52Yy5jb20vWk8tb3Rva00AN2wzODEtNzgzNjY2MADtv3VNFNVSgDXqfGM6K6C5' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='lohithblaze@*************************' session_id='xryzybwzcdwueqdf' app_data='{"file_recording_metadata":{"upload_credentials":{"service_name":"dropbox","token":"*************************"}}}'/></iq> from environment [MucClient id=************************* hostname=*************************]
2021-08-30 02:47:52.986 INFO: [1059] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-08-30 02:47:53.015 INFO: [1059] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=*************************, callName=lohithblaze, urlParams=[])
2021-08-30 02:47:53.016 INFO: [1059] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=*************************, callName=lohithblaze, urlParams=[])), sessionId=xryzybwzcdwueqdf, callLoginParams=XmppCredentials(domain=recorder.*************************, username=recorder, password=*************************))
2021-08-30 02:47:53.017 FINE: [1059] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-08-30 02:47:53.018 FINE: [1059] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-08-30 02:47:53.607 INFO: [1059] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2021-08-30 02:47:53.619 FINE: [1059] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.<init>() Detected os as OS: LINUX
2021-08-30 02:47:53.621 FINE: [1059] org.jitsi.jibri.config.debug() FallbackSupplier: checking for value via suppliers:
  LambdaSupplier: 'JibriConfig::recordingDirectory'
  ConfigSourceSupplier: key: 'jibri.recording.recordings-directory', type: 'kotlin.String', source: 'config'
2021-08-30 02:47:53.621 FINE: [1059] org.jitsi.jibri.config.debug() LambdaSupplier: Trying to retrieve value via JibriConfig::recordingDirectory
2021-08-30 02:47:53.622 FINE: [1059] org.jitsi.jibri.config.debug() LambdaSupplier: 'JibriConfig::recordingDirectory': found value
2021-08-30 02:47:53.622 FINE: [1059] org.jitsi.jibri.config.debug() FallbackSupplier: value found via LambdaSupplier: 'JibriConfig::recordingDirectory'
2021-08-30 02:47:53.627 FINE: [1059] org.jitsi.jibri.config.debug() FallbackSupplier: checking for value via suppliers:
  LambdaSupplier: 'JibriConfig::finalizeRecordingScriptPath'
  ConfigSourceSupplier: key: 'jibri.recording.finalize-script', type: 'kotlin.String', source: 'config'
2021-08-30 02:47:53.628 FINE: [1059] org.jitsi.jibri.config.debug() LambdaSupplier: Trying to retrieve value via JibriConfig::finalizeRecordingScriptPath
2021-08-30 02:47:53.628 FINE: [1059] org.jitsi.jibri.config.debug() LambdaSupplier: 'JibriConfig::finalizeRecordingScriptPath': found value
2021-08-30 02:47:53.630 FINE: [1059] org.jitsi.jibri.config.debug() FallbackSupplier: value found via LambdaSupplier: 'JibriConfig::finalizeRecordingScriptPath'
2021-08-30 02:47:53.630 INFO: [1059] org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>() Writing recording to /recordings/xryzybwzcdwueqdf, finalize script path /usr/bin/jibri_uploader.sh
2021-08-30 02:47:53.631 FINE: [1059] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2021-08-30 02:47:53.633 INFO: [1059] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2021-08-30 02:47:53.634 FINE: [1059] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-08-30 02:47:53.635 INFO: [1059] org.jitsi.jibri.api.xmpp.XmppApi.updatePresence() Jibri reports its status is now JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections
2021-08-30 02:47:53.639 FINE: [1059] org.jitsi.xmpp.mucclient.MucClientManager.log() Setting a presence extension: org.jitsi.xmpp.extensions.jibri.JibriStatusPacketExt@923beaf
2021-08-30 02:47:53.640 FINE: [1059] org.jitsi.xmpp.mucclient.MucClientManager.log() Replacing presence extension: org.jitsi.xmpp.extensions.jibri.JibriStatusPacketExt@305d613
2021-08-30 02:47:53.644 FINE: [37] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element busy-status from namespace http://jitsi.org/protocol/jibri
2021-08-30 02:47:53.644 FINE: [37] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element health-status from namespace http://jitsi.org/protocol/health
2021-08-30 02:47:53.660 INFO: [1059] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-08-30 02:47:55.316 FINE: [1060] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url *************************/lohithblaze#config.iAmRecorder=true&config.externalConnectUrl=null&config.startWithAudioMuted=true&config.startWithVideoMuted=true&interfaceConfig.APP_NAME="Jibri"&config.analytics.disabled=true&config.p2p.enabled=false&config.prejoinPageEnabled=false&config.requireDisplayName=false
2021-08-30 02:47:56.416 FINE: [1060] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-08-30 02:47:56.925 FINE: [1060] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-08-30 02:47:58.067 INFO: [1060] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1775 milliseconds for call page to load
2021-08-30 02:47:58.068 INFO: [1060] org.jitsi.jibri.selenium.JibriSelenium.<init>() Starting empty call check with a timeout of PT30S
2021-08-30 02:47:58.083 INFO: [1060] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2021-08-30 02:47:58.088 INFO: [1060] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2021-08-30 02:47:58.117 INFO: [1060] org.jitsi.jibri.util.JibriSubprocess.ffmpeg.launch() Starting ffmpeg with command ffmpeg -y -v info -f x11grab -draw_mouse 0 -r 30 -s 1280x720 -thread_queue_size 4096 -i :0.0+0,0 -f alsa -thread_queue_size 4096 -i plug:bsnoop -acodec aac -strict -2 -ar 44100 -b:a 128k -af aresample=async=1 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /recordings/xryzybwzcdwueqdf/lohithblaze_2021-08-30-02-47-53.mp4 ([ffmpeg, -y, -v, info, -f, x11grab, -draw_mouse, 0, -r, 30, -s, 1280x720, -thread_queue_size, 4096, -i, :0.0+0,0, -f, alsa, -thread_queue_size, 4096, -i, plug:bsnoop, -acodec, aac, -strict, -2, -ar, 44100, -b:a, 128k, -af, aresample=async=1, -c:v, libx264, -preset, veryfast, -profile:v, main, -level, 3.1, -pix_fmt, yuv420p, -r, 30, -crf, 25, -g, 60, -tune, zerolatency, -f, mp4, /recordings/xryzybwzcdwueqdf/lohithblaze_2021-08-30-02-47-53.mp4])
2021-08-30 02:47:59.302 INFO: [1065] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2021-08-30 02:47:59.306 INFO: [1065] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2021-08-30 02:47:59.307 INFO: [1065] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq <iq to='jibribrewery@*************************/focus' id='t2MyL-2152' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='on'/></iq>
2021-08-30 02:48:13.122 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, num participants: 1, numMutedParticipants: 1, numJigasis: 0, all clients muted? true
2021-08-30 02:48:18.618 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-08-30 02:48:28.118 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=0, upload=0}, download=0, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 1, numJigasis: 0, all clients muted? true

These are the logs for starting the recording, let me know if you need full log files. This happens every time when we start a recording.

[LohithBlaze]

What is the usual time taken for jibri to start recording?

[bbaldino]

Looks like it takes a decent amount of time to join the page, which could be the chrome sluggishness I mentioned above. Did you try what I suggested?

[LohithBlaze]

This is happening everytime, if Chrome is open, then it shouldn't happen everytime right?

Also, how to prime Chrome by the way?

[LohithBlaze]

any idea if any bash script to keep chrome running will help?

[bbaldino]

Is the machine rebooting after each session? I don't think you need to keep chrome running, just start it up after reboot. I think @aaronkvanmeerten is more familiar with what we've done.

[LohithBlaze]

@aaronkvanmeerten any idea or reference link that you can point me to?

[gtilflm]

@bbaldino and @aaronkvanmeerten: I may be having a similar issue on my end. Can either of you help out with the "priming Chrome" idea, or if there is a better solution?

@LohithBlaze: Did you end up getting this figured out?

[bbaldino]

@aaronkvanmeerten was the mastermind behind it, but I'm pretty sure it just comprised of starting chrome up on boot, as it does a fair bit of initialization that first time.

[ProdigyView]

Also have the issue of Chrome being slow the first time starting and looking how to prime it.

[Smatnemo]

Hi, my setup has a total of about 10 seconds as well. Is there a way to speed this up? Has anyone implemented it?

[saghul]

The Docker setup does priming as well now. Debian has been doing it for a bit IIRC.

Have you tested the latest version?

[Smatnemo]

The Docker setup does priming as well now. Debian has been doing it for a bit IIRC.

Have you tested the latest version?

I am currently using the latest jibri i could install. I have moved the setting to a faster more powerful vm and it is now only 4 seconds. I am not using docker. Has anyone got faster or better performance?