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

fix(logging): incorrect FPS logging #10921

Merged
merged 3 commits into from
Jan 31, 2025
Merged

Conversation

TNeutron
Copy link
Contributor

Description of Change

The code provides fixes incorrect FPS calculation issue. The last_frame variable needs to be updated on each iteration, Immediately after computing the FPS of previous.

Before this commit - the last frame was being updated only once at the beginning of stream_handler function. The fps and avg_frame_time computation were completely wrong. This commit fixes the computation.

This commit - updates last_frame variable on each iteration. results is correct fps calculation.

Tests scenarios

I have tested my Pull Request on latest Arduino-esp32 core with ESP32-CAM (CAMERA_MODEL_AI_THINKER) with Core Debug Level - Verbose

Related links

Please provide links to related issue, PRs etc.

(eg. Closes #number of issue)
Closes 1 issue ( #10920 )

@CLAassistant
Copy link

CLAassistant commented Jan 31, 2025

CLA assistant check
All committers have signed the CLA.

Copy link
Contributor

github-actions bot commented Jan 31, 2025

Warnings
⚠️

Some issues found for the commit messages in this PR:

  • the commit message "fix(loggin): Incorrect FPS computation fixed":
    • body's lines must not be longer than 100 characters

Please fix these commit messages - here are some basic tips:

  • follow Conventional Commits style
  • correct format of commit message should be: <type/action>(<scope/component>): <summary>, for example fix(esp32): Fixed startup timeout issue
  • allowed types are: change,ci,docs,feat,fix,refactor,remove,revert,test
  • sufficiently descriptive message summary should be between 10 to 72 characters and start with upper case letter
  • avoid Jira references in commit messages (unavailable/irrelevant for our customers)

TIP: Install pre-commit hooks and run this check when committing (uses the Conventional Precommit Linter).

👋 Hello TNeutron, we appreciate your contribution to this project!


📘 Please review the project's Contributions Guide for key guidelines on code, documentation, testing, and more.

🖊️ Please also make sure you have read and signed the Contributor License Agreement for this project.

Click to see more instructions ...


This automated output is generated by the PR linter DangerJS, which checks if your Pull Request meets the project's requirements and helps you fix potential issues.

DangerJS is triggered with each push event to a Pull Request and modify the contents of this comment.

Please consider the following:
- Danger mainly focuses on the PR structure and formatting and can't understand the meaning behind your code or changes.
- Danger is not a substitute for human code reviews; it's still important to request a code review from your colleagues.
- Resolve all warnings (⚠️ ) before requesting a review from human reviewers - they will appreciate it.
- To manually retry these Danger checks, please navigate to the Actions tab and re-run last Danger workflow.

Review and merge process you can expect ...


We do welcome contributions in the form of bug reports, feature requests and pull requests.

1. An internal issue has been created for the PR, we assign it to the relevant engineer.
2. They review the PR and either approve it or ask you for changes or clarifications.
3. Once the GitHub PR is approved we do the final review, collect approvals from core owners and make sure all the automated tests are passing.
- At this point we may do some adjustments to the proposed change, or extend it by adding tests or documentation.
4. If the change is approved and passes the tests it is merged into the default branch.

Generated by 🚫 dangerJS against b4bf578

@TNeutron TNeutron changed the title Fixed FPS calculation logging fix: incorrect FPS logging Jan 31, 2025
@TNeutron TNeutron changed the title fix: incorrect FPS logging fix(logging): incorrect FPS logging Jan 31, 2025
Previously, last_frame was only updated once at the beginning of stream_handler,
leading to incorrect FPS and avg_frame_time computation.

This commit ensures last_frame is updated on each iteration after last FPS computation,
resulting in accurate FPS logging.

Fixes espressif#10920
@me-no-dev
Copy link
Member

Hi @TNeutron . I see the problem, but what you suggest is not the solution. last_frame = fr_end; should be added after the frame time is calculated by int64_t frame_time = fr_end - last_frame; in order to reset the time. Line 284 should become

int64_t frame_time = fr_end - last_frame;
last_frame = fr_end;
//...

@TNeutron
Copy link
Contributor Author

Hi @TNeutron . I see the problem, but what you suggest is not the solution. last_frame = fr_end; should be added after the frame time is calculated by int64_t frame_time = fr_end - last_frame; in order to reset the time. Line 284 should become

int64_t frame_time = fr_end - last_frame;
last_frame = fr_end;
//...

@me-no-dev
You are correct. I have tested & verify it working.
Log samples given below -

10:38:06.039 -> [  8154][I][app_httpd.cpp:303] stream_handler(): MJPG: 5338B 12ms (83.33fps), AVG: 210ms (4.76fps)
10:38:06.080 -> [  8177][I][app_httpd.cpp:303] stream_handler(): MJPG: 5376B 23ms (43.48fps), AVG: 209ms (4.78fps)
10:38:06.122 -> [  8214][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 37ms (27.03fps), AVG: 209ms (4.78fps)
10:38:06.122 -> [  8237][I][app_httpd.cpp:303] stream_handler(): MJPG: 5881B 22ms (45.45fps), AVG: 209ms (4.78fps)
10:38:06.157 -> [  8255][I][app_httpd.cpp:303] stream_handler(): MJPG: 5042B 18ms (55.56fps), AVG: 209ms (4.78fps)
10:38:06.189 -> [  8283][I][app_httpd.cpp:303] stream_handler(): MJPG: 5881B 27ms (37.04fps), AVG: 209ms (4.78fps)
10:38:06.189 -> [  8304][I][app_httpd.cpp:303] stream_handler(): MJPG: 6046B 21ms (47.62fps), AVG: 208ms (4.81fps)
10:38:06.223 -> [  8337][I][app_httpd.cpp:303] stream_handler(): MJPG: 6046B 33ms (30.30fps), AVG: 206ms (4.85fps)
10:38:06.264 -> [  8356][I][app_httpd.cpp:303] stream_handler(): MJPG: 6046B 18ms (55.56fps), AVG: 204ms (4.90fps)
10:38:06.298 -> [  8384][I][app_httpd.cpp:303] stream_handler(): MJPG: 6046B 27ms (37.04fps), AVG: 205ms (4.88fps)
10:38:06.298 -> [  8404][I][app_httpd.cpp:303] stream_handler(): MJPG: 6046B 20ms (50.00fps), AVG: 204ms (4.90fps)
10:38:06.336 -> [  8425][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 20ms (50.00fps), AVG: 204ms (4.90fps)
10:38:06.336 -> [  8451][I][app_httpd.cpp:303] stream_handler(): MJPG: 5519B 26ms (38.46fps), AVG: 204ms (4.90fps)
10:38:06.406 -> [  8502][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 51ms (19.61fps), AVG: 206ms (4.85fps)
10:38:06.406 -> [  8515][I][app_httpd.cpp:303] stream_handler(): MJPG: 5297B 12ms (83.33fps), AVG: 205ms (4.88fps)
10:38:06.439 -> [  8551][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 36ms (27.78fps), AVG: 205ms (4.88fps)
10:38:06.479 -> [  8571][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 19ms (52.63fps), AVG: 205ms (4.88fps)
10:38:06.513 -> [  8596][I][app_httpd.cpp:303] stream_handler(): MJPG: 7149B 24ms (41.67fps), AVG: 206ms (4.85fps)

Please let me know if you'd like me to edit the commit.
Appreciate your response.

@me-no-dev
Copy link
Member

Yes please :) revert your change and add the new one and we will merge it

@me-no-dev
Copy link
Member

The average frame rate looks a bit weird. Like 10 times lower than it should be... I wonder why

Corrected and tested change in FPS computation, suggested by @me-no-dev and found working with correct numbers.

Previously, last_frame was only updated once at the beginning of stream_handler,
leading to incorrect FPS and avg_frame_time computation.

This commit ensures last_frame is updated on each iteration after last FPS computation,
resulting in accurate FPS logging.

Fixes espressif#10920
@TNeutron
Copy link
Contributor Author

Dear @me-no-dev
I have reverted and added the change as you mentioned.

Both FPS and Avg FPS is correct now.
Here is the log camera stream log taken from this commit -

14:51:03.753 -> [ 10931][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 47ms (21.3fps), AVG: 32ms (31.2fps)
14:51:03.753 -> [ 10955][I][app_httpd.cpp:290] stream_handler(): MJPG: 6176B 24ms (41.7fps), AVG: 32ms (31.2fps)
14:51:03.785 -> [ 10988][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 32ms (31.2fps), AVG: 33ms (30.3fps)
14:51:03.829 -> [ 11008][I][app_httpd.cpp:290] stream_handler(): MJPG: 6606B 19ms (52.6fps), AVG: 30ms (33.3fps)
14:51:03.862 -> [ 11064][I][app_httpd.cpp:290] stream_handler(): MJPG: 6606B 56ms (17.9fps), AVG: 32ms (31.2fps)
14:51:03.902 -> [ 11081][I][app_httpd.cpp:290] stream_handler(): MJPG: 6606B 16ms (62.5fps), AVG: 31ms (32.3fps)
14:51:03.902 -> [ 11112][I][app_httpd.cpp:290] stream_handler(): MJPG: 7081B 30ms (33.3fps), AVG: 31ms (32.3fps)
14:51:03.935 -> [ 11134][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 22ms (45.5fps), AVG: 31ms (32.3fps)
14:51:03.981 -> [ 11163][I][app_httpd.cpp:290] stream_handler(): MJPG: 7074B 28ms (35.7fps), AVG: 31ms (32.3fps)
14:51:04.028 -> [ 11210][I][app_httpd.cpp:290] stream_handler(): MJPG: 7074B 47ms (21.3fps), AVG: 32ms (31.2fps)
14:51:04.072 -> [ 11282][I][app_httpd.cpp:290] stream_handler(): MJPG: 5928B 71ms (14.1fps), AVG: 34ms (29.4fps)
14:51:04.150 -> [ 11338][I][app_httpd.cpp:290] stream_handler(): MJPG: 6073B 56ms (17.9fps), AVG: 34ms (29.4fps)
14:51:04.191 -> [ 11400][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 61ms (16.4fps), AVG: 36ms (27.8fps)
14:51:04.227 -> [ 11424][I][app_httpd.cpp:290] stream_handler(): MJPG: 6471B 24ms (41.7fps), AVG: 35ms (28.6fps)
14:51:04.274 -> [ 11455][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 30ms (33.3fps), AVG: 34ms (29.4fps)
14:51:04.311 -> [ 11501][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 45ms (22.2fps), AVG: 35ms (28.6fps)
14:51:04.311 -> [ 11521][I][app_httpd.cpp:290] stream_handler(): MJPG: 6769B 20ms (50.0fps), AVG: 34ms (29.4fps)
14:51:04.351 -> [ 11544][I][app_httpd.cpp:290] stream_handler(): MJPG: 8132B 22ms (45.5fps), AVG: 35ms (28.6fps)
14:51:04.383 -> [ 11576][I][app_httpd.cpp:290] stream_handler(): MJPG: 6473B 31ms (32.3fps), AVG: 35ms (28.6fps)
14:51:04.383 -> [ 11593][I][app_httpd.cpp:290] stream_handler(): MJPG: 7084B 16ms (62.5fps), AVG: 34ms (29.4fps)
14:51:04.419 -> [ 11628][I][app_httpd.cpp:290] stream_handler(): MJPG: 9427B 35ms (28.6fps), AVG: 34ms (29.4fps)
14:51:04.459 -> [ 11647][I][app_httpd.cpp:290] stream_handler(): MJPG: 8255B 19ms (52.6fps), AVG: 34ms (29.4fps)
14:51:04.505 -> [ 11681][I][app_httpd.cpp:290] stream_handler(): MJPG: 7861B 33ms (30.3fps), AVG: 34ms (29.4fps)
14:51:04.537 -> [ 11742][I][app_httpd.cpp:290] stream_handler(): MJPG: 7000B 60ms (16.7fps), AVG: 36ms (27.8fps)
14:51:04.570 -> [ 11774][I][app_httpd.cpp:290] stream_handler(): MJPG: 7000B 32ms (31.2fps), AVG: 34ms (29.4fps)
14:51:04.603 -> [ 11794][I][app_httpd.cpp:290] stream_handler(): MJPG: 7000B 20ms (50.0fps), AVG: 35ms (28.6fps)
14:51:04.603 -> [ 11810][I][app_httpd.cpp:290] stream_handler(): MJPG: 7861B 16ms (62.5fps), AVG: 34ms (29.4fps)
14:51:04.637 -> [ 11847][I][app_httpd.cpp:290] stream_handler(): MJPG: 6059B 36ms (27.8fps), AVG: 35ms (28.6fps)
14:51:04.673 -> [ 11866][I][app_httpd.cpp:290] stream_handler(): MJPG: 6533B 19ms (52.6fps), AVG: 34ms (29.4fps)
14:51:04.705 -> [ 11898][I][app_httpd.cpp:290] stream_handler(): MJPG: 6874B 31ms (32.3fps), AVG: 33ms (30.3fps)
14:51:04.705 -> [ 11914][I][app_httpd.cpp:290] stream_handler(): MJPG: 7060B 16ms (62.5fps), AVG: 31ms (32.3fps)
14:51:04.741 -> [ 11951][I][app_httpd.cpp:290] stream_handler(): MJPG: 7060B 36ms (27.8fps), AVG: 30ms (33.3fps)
14:51:04.781 -> [ 11971][I][app_httpd.cpp:290] stream_handler(): MJPG: 8641B 19ms (52.6fps), AVG: 28ms (35.7fps)
14:51:04.827 -> [ 12001][I][app_httpd.cpp:290] stream_handler(): MJPG: 7287B 30ms (33.3fps), AVG: 28ms (35.7fps)
14:51:04.871 -> [ 12060][I][app_httpd.cpp:290] stream_handler(): MJPG: 6910B 59ms (16.9fps), AVG: 29ms (34.5fps)
14:51:04.871 -> [ 12081][I][app_httpd.cpp:290] stream_handler(): MJPG: 6910B 20ms (50.0fps), AVG: 28ms (35.7fps)
14:51:04.904 -> [ 12103][I][app_httpd.cpp:290] stream_handler(): MJPG: 7468B 21ms (47.6fps), AVG: 28ms (35.7fps)
14:51:04.937 -> [ 12139][I][app_httpd.cpp:290] stream_handler(): MJPG: 7923B 36ms (27.8fps), AVG: 29ms (34.5fps)
14:51:05.012 -> [ 12195][I][app_httpd.cpp:290] stream_handler(): MJPG: 6339B 56ms (17.9fps), AVG: 30ms (33.3fps)
14:51:05.012 -> [ 12216][I][app_httpd.cpp:290] stream_handler(): MJPG: 5950B 20ms (50.0fps), AVG: 30ms (33.3fps)
14:51:05.089 -> [ 12298][I][app_httpd.cpp:290] stream_handler(): MJPG: 6681B 82ms (12.2fps), AVG: 33ms (30.3fps)
14:51:05.131 -> [ 12318][I][app_httpd.cpp:290] stream_handler(): MJPG: 7029B 19ms (52.6fps), AVG: 33ms (30.3fps)
14:51:05.209 -> [ 12389][I][app_httpd.cpp:290] stream_handler(): MJPG: 7029B 71ms (14.1fps), AVG: 34ms (29.4fps)
14:51:05.209 -> [ 12412][I][app_httpd.cpp:290] stream_handler(): MJPG: 7923B 22ms (45.5fps), AVG: 33ms (30.3fps)
14:51:05.245 -> [ 12437][I][app_httpd.cpp:290] stream_handler(): MJPG: 6174B 25ms (40.0fps), AVG: 32ms (31.2fps)
14:51:05.245 -> [ 12454][I][app_httpd.cpp:290] stream_handler(): MJPG: 6791B 17ms (58.8fps), AVG: 32ms (31.2fps)
14:51:05.277 -> [ 12481][I][app_httpd.cpp:290] stream_handler(): MJPG: 6015B 26ms (38.5fps), AVG: 33ms (30.3fps)
14:51:05.313 -> [ 12523][I][app_httpd.cpp:290] stream_handler(): MJPG: 6928B 41ms (24.4fps), AVG: 33ms (30.3fps)
14:51:05.347 -> [ 12556][I][app_httpd.cpp:290] stream_handler(): MJPG: 9079B 33ms (30.3fps), AVG: 34ms (29.4fps)
14:51:05.392 -> [ 12579][I][app_httpd.cpp:290] stream_handler(): MJPG: 7613B 22ms (45.5fps), AVG: 33ms (30.3fps)
14:51:05.424 -> [ 12603][I][app_httpd.cpp:290] stream_handler(): MJPG: 7613B 24ms (41.7fps), AVG: 33ms (30.3fps)
14:51:05.424 -> [ 12626][I][app_httpd.cpp:290] stream_handler(): MJPG: 8491B 22ms (45.5fps), AVG: 33ms (30.3fps)
14:51:05.461 -> [ 12653][I][app_httpd.cpp:290] stream_handler(): MJPG: 7453B 26ms (38.5fps), AVG: 33ms (30.3fps)
14:51:05.461 -> [ 12670][I][app_httpd.cpp:290] stream_handler(): MJPG: 6488B 17ms (58.8fps), AVG: 32ms (31.2fps)
14:51:05.498 -> [ 12690][I][app_httpd.cpp:290] stream_handler(): MJPG: 7441B 19ms (52.6fps), AVG: 30ms (33.3fps)
14:51:05.498 -> [ 12707][I][app_httpd.cpp:290] stream_handler(): MJPG: 7029B 17ms (58.8fps), AVG: 30ms (33.3fps)
14:51:05.577 -> [ 12757][I][app_httpd.cpp:290] stream_handler(): MJPG: 7029B 49ms (20.4fps), AVG: 32ms (31.2fps)
14:51:05.622 -> [ 12788][I][app_httpd.cpp:290] stream_handler(): MJPG: 8170B 31ms (32.3fps), AVG: 31ms (32.3fps)
14:51:05.669 -> [ 12833][I][app_httpd.cpp:290] stream_handler(): MJPG: 6402B 45ms (22.2fps), AVG: 31ms (32.3fps)

I'm still learning my way around git. Again, I appreciate your patience and kind response :) Looking forward to the merge 😅

@me-no-dev me-no-dev added the Status: Pending Merge Pull Request is ready to be merged label Jan 31, 2025
Copy link
Contributor

Memory usage test (comparing PR against master branch)

The table below shows the summary of memory usage change (decrease - increase) in bytes and percentage for each target.

MemoryFLASH [bytes]FLASH [%]RAM [bytes]RAM [%]
TargetDECINCDECINCDECINCDECINC
ESP32S30‼️ +5K0.00⚠️ +0.500⚠️ +4960.00⚠️ +0.83
ESP32S20‼️ +4K0.00⚠️ +0.400⚠️ +120.00⚠️ +0.02
ESP320‼️ +12K0.00‼️ +1.230⚠️ +680.00⚠️ +0.11
Click to expand the detailed deltas report [usage change in BYTES]
TargetESP32S3ESP32S2ESP32
ExampleFLASHRAMFLASHRAMFLASHRAM
ESP32/examples/Camera/CameraWebServer‼️ +5K⚠️ +496‼️ +4K⚠️ +12‼️ +12K⚠️ +68

@me-no-dev me-no-dev merged commit 0302b4d into espressif:master Jan 31, 2025
25 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Pending Merge Pull Request is ready to be merged
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants