Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stream progressively falls behind real-time (v1.3.0) #330

Closed
bbobrian opened this issue Mar 28, 2022 · 52 comments
Closed

Stream progressively falls behind real-time (v1.3.0) #330

bbobrian opened this issue Mar 28, 2022 · 52 comments
Labels
bug Something isn't working

Comments

@bbobrian
Copy link

The video stream slowly falls back in time, witnessed in the timestamp displayed behind the actual time. It get's progressively worse and is eventually several minutes behind. I compared the stream timestamp to the date from inside the docker container. I noticed this today when I received a person detection notification of myself about 5 minutes after it actually happened.

Restarting the docker container brings it back to real-time but then it slowly falls back again.

Also seeing this continually repeating in the log:
2022/03/28 18:33:03 [wyzecam.tutk.tutk_ioctl_mux][INFO][Front Porch] Now listening on channel id 0
2022/03/28 18:33:04 [wyzecam.tutk.tutk_ioctl_mux][INFO][Front Porch] No longer listening on channel id 0
2022/03/28 18:33:29 [wyzecam.tutk.tutk_ioctl_mux][INFO][Front Porch] Now listening on channel id 0
2022/03/28 18:33:29 [wyzecam.tutk.tutk_ioctl_mux][INFO][Front Porch] Now listening on channel id 0
2022/03/28 18:33:30 [wyzecam.tutk.tutk_ioctl_mux][INFO][Front Porch] No longer listening on channel id 0

@mrlt8
Copy link
Owner

mrlt8 commented Mar 29, 2022

Can confirm the delay. It's probably coming from the sleep between the frames.

As for the ioctl messages, that's to monitor the bitrate and FPS every 500 frames as those two values are missing from in frame_info. I don't think it's causing the delay, but I can change it to every 1000 frames to see if it helps.

@mrlt8 mrlt8 added the bug Something isn't working label Mar 29, 2022
@bbobrian
Copy link
Author

Maybe change those messages to DEBUG level if they are going to happen every 20-40 seconds.

@dnestico
Copy link

dnestico commented Mar 29, 2022

Yea can confirm the same, it starts off real time then can go down to more then 10 minutes behind sometimes.

Hopefully webRTC can fix this but I disabled that because all that did for me was generate URLs in the log but no stream URL, also showed no stream. :/

@tavicu
Copy link

tavicu commented Mar 29, 2022

Same problem after updating to the latest version.

Also i've seen an increase of CPU usage from 8% to 22%.

For now I have reverted to 1.2.2 and it's all good!

@mrlt8
Copy link
Owner

mrlt8 commented Mar 29, 2022

Maybe change those messages to DEBUG level if they are going to happen every 20-40 seconds.

That's coming from the kroo/wyzecam library when DEBUG_LEVEL is set, but we could turn that off.

Also i've seen an increase of CPU usage from 8% to 22%.

Is that jump on the DEV or v1.3.0 build? I do see an increase in CPU usage on the DEV build

It also seems like the latest build of ffmpeg might have slipped into the final release of v1.3.0, but I don't think the lag is coming from that.

@tavicu
Copy link

tavicu commented Mar 29, 2022

Is that jump on the DEV or v1.3.0 build? I do see an increase in CPU usage on the DEV build

on :latest which I suppose is 1.3.0

@Z1mDMan
Copy link

Z1mDMan commented Mar 29, 2022

Same problem after updating to the latest version.

Also i've seen an increase of CPU usage from 8% to 22%.

For now I have reverted to 1.2.2 and it's all good!

Same here. I'm doing the same work-around for now.

@dnestico
Copy link

So just realized this explains why my camera notification snapshots are wrong. Wow

@hoveeman
Copy link

Interestingly my v3 camera does not exhibit the time sync issue. It is still correct. However, my v2 cameras exhibit this and continue to drift in time.

@dnestico
Copy link

dnestico commented Mar 30, 2022

I have:

2 v2's
1 v3
1 DB

As you can see in the screenshot they're all behind, which is strange, because I think the last update they were near real time. Hope there's a fix for this.

Screen Shot 2022-03-29 at 8 30 17 PM

Screen Shot 2022-03-29 at 8 30 07 PM

Another example:

Screenshot_20220330-052739.png

Screenshot_20220330-052812.png

@mrlt8
Copy link
Owner

mrlt8 commented Mar 30, 2022

Also i've seen an increase of CPU usage from 8% to 22%.

8 to 22 is quite a jump. I actually see a drop in CPU usage with 1.3.0.

The problem with this bug is that if we if we request the frames too soon, we get the NOREADY error until a frame is received and a slight CPU spike, but leave too much time in between and the stream starts to lag.

@dnestico is the delay still present on the DEV build?

mrlt8 added a commit that referenced this issue Mar 30, 2022
@dnestico
Copy link

@mrlt8

I am not on the dev build sorry. How can I switch?

@mrlt8
Copy link
Owner

mrlt8 commented Mar 31, 2022

If using docker:

mrlt8/wyze-bridge:dev

Or if using HA:

Open your Home Assistant instance and show the add add-on repository dialog with a specific repository URL pre-filled.

@dnestico
Copy link

Alright will check this out soon.

@dreondre
Copy link

I’ve been running dev for about an hour now and so far so good. However, I’ll likely check again in the morning or in the middle of the night.

@dnestico
Copy link

So should I remove the public one first and replace it with the dev right?

@dreondre
Copy link

I've been on the dev branch for 12 hours now and it appears to be keeping in time now. This looks a lot better. 👍

mrlt8 added a commit that referenced this issue Mar 31, 2022
* Reduce sleep between frames and FFMPEG cmds #330

* Wyze App version bump

* adjust sleep based on last frame #330

* Use `_` for camera names in ENV and fix typos #332
@mrlt8
Copy link
Owner

mrlt8 commented Mar 31, 2022

Pushed v1.3.1 which seems to be better (still see the usual 1.5-ish seconds delay compared to the app) without any major CPU spikes.

@tavicu can you see if you're still seeing a major jump in cpu usage?

@dnestico you should be able to have multiple versions installed for testing.

@Z1mDMan
Copy link

Z1mDMan commented Mar 31, 2022

I grabbed the nightly yesterday and this morning my cameras were lagging again so I went back to 1.2.2

@tavicu
Copy link

tavicu commented Mar 31, 2022

@tavicu can you see if you're still seeing a major jump in cpu usage?

Updated and with 1.3.1 everything looks ok! The CPU is back to normal and the delay is around 2 seconds :)
Thank you for the quick fix!

@bbobrian
Copy link
Author

Pushed v1.3.1 which seems to be better (still see the usual 1.5-ish seconds delay compared to the app) without any major CPU spikes.

Running great for me as well. Thanks!

@mrlt8
Copy link
Owner

mrlt8 commented Apr 3, 2022

Marking this as resolved for now.

@mrlt8 mrlt8 closed this as completed Apr 3, 2022
@Z1mDMan
Copy link

Z1mDMan commented Apr 4, 2022

I can confirm resolved in 1.3.1 here. Thanks!

@dnestico
Copy link

dnestico commented Apr 6, 2022

Same!

@dnestico
Copy link

dnestico commented Apr 9, 2022

So this is defenitley resolved yes but it seems with multiple cameras this still sometimes happens, I have 4 cameras on the hub and sometimes I'll go to look at my doorbell and it will be 2 hours behind while the rest are on time, or sometimes 1 camera will be behind by a couple minutes like 20-30 still... Screenshot_20220409-195524.pngScreenshot_20220409-195530.png

@dnestico
Copy link

dnestico commented Apr 10, 2022

I just checked and the doorbell was the only stream that was 3 hours behind, while one of my other cams was "unavailable"... Again, not offline in the wyze app though

Edit: that camera just came back online on the bridge, but the doorbell still about 3 hours behind, also one thing I don't get with the snapshot service is the camera I have taking snapshots for certian events isn't delayed ATM, but when it sends me the snapshot in the notification it's from 24 hours ago... So weird.

@mrlt8
Copy link
Owner

mrlt8 commented Apr 10, 2022

3 hours is a huge delay! Any memory or playback issues?

Anyone else still experiencing significant lag on 1.3.1+?

As for the unavailable cam, can you please post logs? there should hopefully be something there showing it go down in the bridge.

@bbobrian
Copy link
Author

1.3.1 working perfect for me, but I only have a single V3 camera. CPU 0.5% and memory at 59MB.

@dnestico
Copy link

dnestico commented Apr 10, 2022

@mrlt8

Aii so just restarted HA twice and removed 2 cameras, so down to 4 in HA.

The doorbell was 2 hours behind the rest while 1 is reported as unavailable, but it isn't in the Wyze app, the logs just said the usual "Camera is down".


I restarted HA for the 3rd time andddd the doorbell is no longer behind the rest, just like normally happens.

Also, the camera that was offline, is now longer offline either. Just a constant loop it seems.

@dnestico
Copy link

dnestico commented Apr 10, 2022

I am going to keep an eye on it for the next couple of hours, but the doorbell is strange because 5 minutes after checking it, the stream dropped to 1 minute behind the rest.

I am gonna the developer page and the docker logs page open in the background for the next hour or couple and every so often check the doorbell stream to see what happens.

Update coming soon.

@dnestico
Copy link

dnestico commented Apr 11, 2022

I left HA developer page / wyze hub logs open in the background for a couple hours:

UPDATES:

20 minutes: doorbell stream fell back 5 mins

50 minutes: doorbell stream fell back 15 mins

1 hour 15 minutes later: doorbell stream fell back 20 mins

1 hour 28 minutes later: garage cam (v2) went unavailable, not in wyze app though

LOG FOR THIS EVENT:
2022/04/10 16:37:55 [Garage Cam] WARNING: Skipping smaller frame at start of stream (frame_size=1)
2022/04/10 16:38:02 [RTSP][GARAGE-CAM] 📖 New client reading
2022/04/10 16:38:04 [RTSP][GARAGE-CAM] 📕 Client stopped reading
2022/04/10 16:38:14 [RTSP][GARAGE-CAM] 📖 New client reading
2022/04/10 16:38:15 [RTSP][GARAGE-CAM] ❌ '/garage-cam' stream is down
2022/04/10 16:38:15 [RTSP][GARAGE-CAM] 📕 Client stopped reading
2022/04/10 16:38:15 [RTSP][GARAGE-CAM] 📕 Client stopped reading

1 hour 40 mins later: garage cam (v2) came back...
I opened the wyze app to check if it was offline during this time it was on HA and it was not, it was shortly after I checked wyze app it came back online in HA...

LOG FOR THIS EVENT:
2022/04/10 16:48:48 [Garage Cam] WARNING: Waiting for keyframe
2022/04/10 16:48:50 [Garage Cam] [Errno 32] Broken pipe
2022/04/10 16:48:51 [WyzeBridge] 🎉 Connecting to WyzeCam V2 - Garage Cam on 192.168.2.31 (1/3)
2022/04/10 16:48:54 [Garage Cam] 📡 Getting 120kb/s HD stream (15fps) via LAN mode (WiFi: 75%) FW: 4.9.8.1002 🔒 (DTLS) (2/3)
2022/04/10 16:48:54 [RTSP][GARAGE-CAM] ✅ '/garage-cam' stream is UP! (3/3)
2022/04/10 16:48:54 [RTSP][GARAGE-CAM] 📖 New client reading

2 hours 20 minutes later: the doorbell stream is 1 hour and 18 minutes behind, nothing in the logs

3 hours later: the doorbell stream is now 2 hours behind

This is where I will end this reply, just wanted to try and help you out as much as possible.

Also once again, here is my config:

WYZE_EMAIL: (removed)
WYZE_PASSWORD: (removed)
NET_MODE: ANY
SNAPSHOT: RTSP15
MQTT_DTOPIC: homeassistant
ROTATE_DOOR: true
WEBRTC: false
FRESH_DATA: true
RTSP_READTIMEOUT: 20s
KEEP_BAD_FRAMES: false
FPS_FIX: false
FILTER_BLOCK: true
FILTER_MACS: (removed), (removed)

Screen Shot 2022-04-10 at 8 05 10 PM

@mrlt8
Copy link
Owner

mrlt8 commented Apr 11, 2022

From what you posted, it seems to be falling behind at a rate of about 15s every min. So the time stamp should be moving a little slower when viewing the stream live.

The problem with such a large delay is that the frames have to get buffered somewhere, so your memory usage should be skyrocketing.

Since it's only the doorbell that is slowing down, can you disable the rotation to see if that is where the bottleneck is?

@dnestico
Copy link

dnestico commented Apr 11, 2022

Something weird that just happened is the garage camera went offline in HA, not the wyze app... and right as that happened the doorbell streamed jumped right ahead to near real time... weird.

And yes, I will do so.


EDIT:

Ok I turned rotate off and will have to see tomorrow if that delay returns, as of right now, its in sync with the other cameras and the garage cam also came back too.

@mrlt8
Copy link
Owner

mrlt8 commented Apr 12, 2022

@dnestico Is the doorbell staying up to speed with the rest of the cameras when rotation is off?

@dnestico
Copy link

I think there must be caching issue with my chrome browser because I just loaded the stream and it was 3 hours behind, I then reload the page and it's in sync with every other camera.

Yesterday it only fell back 10 minutes but right now after reloading the browser page its is up to speed with the rest of the cameras.

Also happy about that commit because I definitely want the doorbell rotated lol, but this is fine for now of course since it seems to be performing a lot better.

@mrlt8
Copy link
Owner

mrlt8 commented Apr 12, 2022

Interesting. I pushed some changes to the dev build that should increase the number of keyframes, so that it should start the rotated video faster. Could you give it a try and see if it helps?

@dnestico
Copy link

dnestico commented Apr 12, 2022

Alright, so I stopped the main branch and started the dev build.

Is there supposed to be duplicate entities? The entities the plugin made give me the Stream URL and the Image URL, so I added them via generic integration and now there are double entities, not a problem but this is normal right?

The entities generated by the docker (dev build) are just still images, the entities I added using the details it gave are the actual live video + snapshot.

This is the setup for the cams btw just in case also using the stream/image URL the dev branch provided.

Screen Shot 2022-04-12 at 2 04 36 PM

@dnestico
Copy link

dnestico commented Apr 12, 2022

I will check back later but after adding all my cameras and the doorbell with rotate on it loaded pretty quick and loaded... but with a 5 minute delay.

That's better than 10 minutes so I'll have to check again in a couple hours.

EDIT:

About 2 hours later and it's now 20 minutes behind the rest. damn.

@dnestico
Copy link

dnestico commented Apr 12, 2022

Welp now it's 2 hours behind, I might just filter it out tbh.

Also is changing the snapshot frequency (like RTSP=15) not on the dev branch?

@mrlt8
Copy link
Owner

mrlt8 commented Apr 13, 2022

Is this with chrome or VLC?
Also, please let the video run for at least 30s to see if it's just a key frame issue.

@dnestico
Copy link

dnestico commented Apr 13, 2022

This is with chrome, I just checked again and now it's 5 mins behind while the thumbnail is from a couple of hours ago. But then again all of my thumbnails are hours behind.

@mrlt8
Copy link
Owner

mrlt8 commented Apr 13, 2022

Please test in VLC or some other external player as the web viewer may be unreliable.

@dnestico
Copy link

Screen Shot 2022-04-12 at 10 05 20 PM

Umm this is... weird, the stream is up on the web player.

@mrlt8
Copy link
Owner

mrlt8 commented Apr 13, 2022

homeassistant.local?

@dnestico
Copy link

That's what I've been using? I'm gonna review the docs again in a couple minutes because I thought that was right as those are the urls the dev branch gave me so I used them.

Screenshot_20220412-221514.pngScreenshot_20220412-221504.png

@dnestico
Copy link

Oh wait I see my error God damn I am an idiot, I will update you soon.

@dnestico
Copy link

dnestico commented Apr 13, 2022

Ok so that worked and it's behind as you can see:

I just compared the two and it is exactly the same as the web player.

Screen Shot 2022-04-12 at 10 37 30 PM

@mrlt8
Copy link
Owner

mrlt8 commented Apr 13, 2022

Thanks for the confirmation. I'll go ahead and split this into a new issue since it only seems to affect the cameras after rotation.

@dnestico
Copy link

dnestico commented Apr 13, 2022

Alright nice, right now the only issue that remains is the thumbnails also aren't updating so I may just switch it to always live rather than auto. I rather not do that due to battery usage though.

Also I hope webRTC can keep the cams online because there is one cam that keeps reporting as unavailable on HA when it isn't offline. :/

Update:

Just restarted the addon again and these issues are gone but will have to see tomorrow as this happened before too.

mrlt8 added a commit that referenced this issue Apr 15, 2022
* Use tee muxer for ffmpeg & add livestream out #334

* HA: make SNAPSHOT optional and add RTSP5 #336

* Bump iOS 15.4.1 and Wyze 2.29.2

* improve performance on doorbell rotation #330

* More keyframes to start rotated video faster #330

* Use reported FPS for cooldown

* Use reported FPS and remove extra livestream services

* version bump and readme
mrlt8 added a commit that referenced this issue Apr 23, 2022
mrlt8 added a commit that referenced this issue Apr 24, 2022
* Clear MQTT topics on exit #338

* Time based keyframes #338

* Speed up snapshots #340

* Limit bitrate on rotation #338 #340

* Don't block on FPS change #340

* Match cases when checking model names #346

* APP_VERSION bump to 2.30.0

* Option to save snapshots as PNG

* tutk_ioctl_mux log level #330

* send_ioctl log level

* Reduce rtsp snap logging #340
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

7 participants