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.

Sign up for GitHub

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

Jump to bottom

the sample kernel/metairq_dispatch fails on nucleo_g474re #35850

Closed
FRASTM opened this issue Jun 1, 2021 · 7 comments
Closed

the sample kernel/metairq_dispatch fails on nucleo_g474re #35850

FRASTM opened this issue Jun 1, 2021 · 7 comments
Assignees
@FRASTM
Labels
bug The issue is a bug, or the PR is fixing a bug platform: STM32 ST Micro STM32 priority: low Low impact/importance bug

Comments

@FRASTM
Copy link
Collaborator

FRASTM commented Jun 1, 2021 •
edited
Loading

Describe the bug
When running the sample kernel/metairq_dispatch/ on the nucleo g474re board, the test fails w/o exiting

To Reproduce
Steps to reproduce the behavior:

  1. west build -p auto -b nucleo_g474re samples/kernel/metairq_dispatch/
  2. See error

Expected behavior

...
I:         ---------- Latency (cyc) ----------                                  
I:             Best    Worst     Mean    Stdev                                  
I: MetaIRQ     4030     7139     5486      344                                  
I: Thread0        0       -1 1520113657 22031308                                
I: Thread1     9327  4308235  2078250  1404305                                  
I: Thread2 12660929 19560086 16253934  2266334                                  
I: Thread3 23756579 32298041 27852013  2626435                                  
I: MetaIRQ Test Complete

Logs and console output

*** Booting Zephyr OS build v2.6.0-rc2-98-gc5e50ef0e219  ***                    
I: Starting Thread0 at priority -2                                              
I: Starting Thread1 at priority -1                                              
I: M0 T1 mirq 5593 disp 9442 proc 33304 real 34495                              
I: M7 T1 mirq 5479 disp 298350 proc 6368 real 7146                              
I: M8 T1 mirq 5480 disp 954541 proc 79986 real 80659                            
I: M21 T1 mirq 5480 disp 801265 prI: Thread 3 queue full, message 39 dropped    
I: Thread 3 queue full, message 40 dropped                                      
oc 11551 real 12776                                                             
I: M29 T1 mirq 5480 disp 2417268 proc 38274 real 38674                          
I: M31 T1 mirq 5480 disp 3034675 proc 40128 real 40926                          
I: M35 T1 mirq 5486 disp 3569342 proc 47628 real 48808                          
I: M36 T1 mirq 5480 disp 4400886 proc 39891 real 40926                          
I: M5 T0 mirq 5480 disp 7486637 proc 19434 real 20666                           
I: M9 T0 mirq 5479 disp 8059180 proc 47379 real 47682                           
I: M13 T0 mirq 5480 disp 8551847 proc 6717 real 7146                            
I: M16 T0 mirq 5486 disp 8991711 proc 77010 real 78084                          
I: M17 T0 mirq 5480 disp 9852535 proc 6207 real 7146                            
I: M18 T0 mirq 5480 disp 10598416 proc 77198 real 78084                         
I: M25 T0 mirq 5480 disp 11014995 proc 51174 real 52186                         
I: M26 T0 mirq 5480 disp 11813675 proc 51041 real 52186                         
I: M28 T0 mirq 5480 disp 12595359 proc 51315 real 52186                         
I: M37 T0 mirq 5480 disp 12765039 proc 39829 real 40926                         
I: Starting Thread2 at priority 0                                               
I: M14 T2 mirq 5480 disp 15751871 proc 47955 real 48808                         
I: M19 T2 mirq 5478 disp 16275181 proc 81274 real 81462                         
I: M23 T2 mirq 5480 disp 16831137 proc 32438 real 33044                         
I: M27 T2 mirq 5486 disp 17457673 proc 67288 real 67950                         
I: M33 T2 mirq 5479 disp 17796047 proc 34288 real 35296                         
I: Starting Thread3 at priority 1                                               
I: M1 T3 mirq 5480 disp 21678397 proc 73034 real 73580                          
I: M2 T3 mirq 5480 disp 22466568 proc 67845 real 69076                          
I: M3 T3 mirq 5486 disp 23216381 proc 4435 real 4894                            
I: M4 T3 mirq 5480 disp 23996262 proc 69046 real 70202                          
I: M6 T3 mirq 5480 disp 24662202 proc 32672 real 33044                          
I: M10 T3 mirq 5486 disp 25188978 proc 21600 real 21784                         
I: M11 T3 mirq 5480 disp 26013159 proc 11983 real 12776                         
I: M12 T3 mirq 5480 disp 26718272 proc 77540 real 78084                         
I: M15 T3 mirq 5480 disp 27321847 proc 17614 real 18406                         
I: M20 T3 mirq 5480 disp 27856998 proc 19381 real 19532                         
I: M22 T3 mirq 5480 disp 28477146 proc 41911 real 42052                         
I: M24 T3 mirq 5480 disp 29248688 proc 77297 real 78084                         
I: M30 T3 mirq 5480 disp 29767262 proc 66159 real 66824                         
I: M32 T3 mirq 5480 disp 30410576 proc 61999 real 62320                         
I: M34 T3 mirq 5486 disp 31117391 proc 9484 real 10524                          
I: M38 T3 mirq 5480 disp 31739778 proc 45412 real 46556

Environment (please complete the following information):

  • OS: ( Linux,s)
  • Toolchain (e.g Zephyr SDK 0.12.4)
  • Commit from V2.6.0.rc2 c5e50ef
@FRASTM FRASTM added bug The issue is a bug, or the PR is fixing a bug platform: STM32 ST Micro STM32 labels Jun 1, 2021
@FRASTM
Copy link
Collaborator Author

FRASTM commented Jun 1, 2021 •
edited
Loading

I Could find that commit 9d4e9f2 from PR #35647 has an impact on this failure, but this cannot be explained in case of running on the stm32g474re nucleo board

@galak galak added the priority: low Low impact/importance bug label Jun 1, 2021
@FRASTM
Copy link
Collaborator Author

FRASTM commented Jun 2, 2021

now passed on 2.6.0-rc3:

*** Booting Zephyr OS build v2.6.0-rc3  ***
I: Starting Thread0 at priority -2
I: Starting Thread1 at priority -1
I: M0 T1 mirq 5505 disp 9354 proc 10229 real 10532
I: M1 T1 mirq 5480 disp 674169 proc 20721 real 21784
I: M4 T1 mirq 5480 disp 1352381 proc 44753 real 50256
I: M7 T1 mirq 5480 disp 1948578 proc 21265 real 22108
I: M11 T1 mirq 5480 disp 2452786 proc 63036 real 63445
I: M12 T1 mirq 5480 disp 3264966 proc 12499 real 12776
I: M14 T1 mirq 5480 disp 3870355 proc 5681 real 6020
I: M15 T1 mirq 5480 disp 4531232 proc 9285 real 10524
I: M16 T1 mirq 5486 disp 5240864 proc 18256 real 18406
I: M29 T1 mirq 5480 disp 4928391 proc 62643 real 63446
I: M35 T1 mirq 5480 disp 5349441 proc 72151 real 72454
I: M38 T1 mirq 5486 disp 6000622 proc 47442 real 47682
I: M40 T1 mirq 4030 disp 6695180 proc 35838 real 36422
I: M2 T0 mirq 5480 disp 10609288 proc 74694 real 75840
I: M9 T0 mirq 5478 disp 11025862 proc 1294 real 1516
I: M17 T0 mirq 5480 disp 11142746 proc 56185 real 56690
I: M18 T0 mirq 5480 disp 11877926 proc 42868 real 43178
I: M23 T0 mirq 5480 disp 12344597 proc 61371 real 62320
I: M30 T0 mirq 5480 disp 12592414 proc 19757 real 20658
I: M32 T0 mirq 5480 disp 13280562 proc 30164 real 30792
I: M33 T0 mirq 5480 disp 14023849 proc 44243 real 45430
I: M34 T0 mirq 5486 disp 14747775 proc 64952 real 65698
I: M36 T0 mirq 5480 disp 15559972 proc 31862 real 33044
I: Starting Thread2 at priority 0
I: M10 T2 mirq 5480 disp 19099915 proc 48955 real 49934
I: M13 T2 mirq 5480 disp 19743282 proc 77860 real 78084
I: M19 T2 mirq 5480 disp 20023860 proc 46607 real 47682
I: M20 T2 mirq 5480 disp 20835181 proc 41442 real 42052
I: M21 T2 mirq 5480 disp 21640583 proc 53638 real 54438
I: M24 T2 mirq 5480 disp 22220511 proc 54410 real 55564
I: M28 T2 mirq 5480 disp 22733565 proc 41550 real 42052
I: M31 T2 mirq 5480 disp 23420106 proc 24505 real 25162
I: Starting Thread3 at priority 1
I: M3 T3 mirq 5485 disp 27055677 proc 56736 real 57816
I: M5 T3 mirq 5479 disp 27811227 proc 64491 real 65698
I: M6 T3 mirq 5480 disp 28591660 proc 55762 real 56690
I: M8 T3 mirq 5480 disp 29346092 proc 23982 real 25162
I: M22 T3 mirq 5480 disp 28880474 proc 32895 real 33044
I: M25 T3 mirq 5480 disp 29422013 proc 71020 real 71328
I: M26 T3 mirq 5480 disp 30256832 proc 5890 real 6020
I: M27 T3 mirq 5480 disp 30949463 proc 5353 real 6020
I: M37 T3 mirq 5480 disp 31081094 proc 29615 real 30792
I: M39 T3 mirq 5480 disp 31773377 proc 74746 real 75832
I:         ---------- Latency (cyc) ----------
I:             Best    Worst     Mean    Stdev
I: MetaIRQ     4030     5505     5446      223
I: Thread0        0       -1 1913688243 57799983
I: Thread1     9354  6695180  3562948  2046455
I: Thread2 19099915 23420106 21214625  1438893
I: Thread3 27055677 31773377 29516791  1428438
I: MetaIRQ Test Complete

@FRASTM FRASTM closed this as completed Jun 2, 2021
@FRASTM
Copy link
Collaborator Author

FRASTM commented Jun 4, 2021

issues appears again on the
SHA1 a02704b
SHA1 95e359d

@FRASTM FRASTM reopened this Jun 4, 2021
@FRASTM
Copy link
Collaborator Author

FRASTM commented Jun 4, 2021

It should be noticed that forcing the LL_FLASH_SetLatency(LL_FLASH_LATENCY_2);
in the drivers/clock_control/clock_stm32_ll_common.c
(end of the stm32_clock_control_init function)
is a workaround to pass the test.

@erwango
Copy link
Member

erwango commented Jun 10, 2021

It should be noticed that forcing the LL_FLASH_SetLatency(LL_FLASH_LATENCY_2); is a workaround to pass the test.

Thanks for this observation, that shows that slowing down the chip has a positive effect or there's a timing related issue. We need to dig further.

@erwango erwango assigned FRASTM and unassigned erwango Jun 10, 2021
@affrinpinhero-2356
Copy link
Contributor

I have run the test and the result was as below:
Commit used for test :
sha1: bf3c6e7

*** Booting Zephyr OS build zephyr-v2.6.0-770-gbf3c6e7ba415  ***
I: Starting Thread0 at priority -2
I: Starting Thread1 at priority -1
I:I: M1 T1 mirq 5515 disp 9394 proc 75174 real 84840
I: M2 T1 mirq 5511 disp 817427 proc 18002 real 24415
I: M14 T1 mirq 5511 disp 575600 proc 22171 real 22910
I: M16 T1 mirq 5511 disp 1232542 proc 61190 real 62320
I: M17 T1 mirq 5511 disp 2060143 proc 79152 real 80336
I: M23 T1 mirq 5511 disp 2498333 proc 36215 real 36422
I: M28 T1 mirq 5511 disp 2977609 proc 65956 real 66824
I: M35 T1 mirq 5511 disp 3487299 proc 16179 real 17280
I: M37 T1 mirq 5511 disp 4109683 proc 26970 real 27414
I: M38 T1 mirq 5511 disp 4902958 proc 66112 real 66824
I: M5 T0 mirq 5511 disp 8184689 proc 80505 real 81470
I: M6 T0 mirq 5511 disp 9017268 proc 72224 real 72454
I: M8 T0 mirq 5511 disp 9602817 proc 19362 real 19532
I: M19 T0 mirq 5511 disp 9547455 proc 20202 real 20658
I: M26 T0 mirq 5511 disp 9914845 proc 16105 real 17280
I: M29 T0 mirq 5511 disp 10486235 proc 12881 real 13902
I: M33 T0 mirq 5517 disp 11140378 proc 40089 real 40926
 Starting Thread2 at priority 0
I: M0 T2 mirq 5630 disp 14794816 proc 60970 real 61194
I: M3 T2 mirq 5517 disp 15571017 proc 14942 real 16154
I: M4 T2 mirq 5511 disp 16380405 proc 1605 real 2642                            
I: M7 T2 mirq 5511 disp 16871130 proc 81180 real 81462                          
I: M11 T2 mirq 5511 disp 17293592 proc 15395 real 16154                         
I: M12 T2 mirq 5511 disp 18083602 proc 23142 real 24036                         
I: M18 T2 mirq 5511 disp 18533684 proc 52038 real 52186                         
I: M20 T2 mirq 5517 disp 19196487 proc 45575 real 46556                         
I: M24 T2 mirq 5511 disp 19802655 proc 78782 real 79210                         
I: M27 T2 mirq 5511 disp 20475484 proc 6634 real 7146                           
I: M30 T2 mirq 5511 disp 21100117 proc 46581 real 47682                         
I: M32 T2 mirq 5511 disp 21894415 proc 40988 real 42052                         
I: M34 T2 mirq 5511 disp 22666081 proc 77432 real 78084                         
I: M39 T2 mirq 5517 disp 23133778 proc 74279 real 74706                         
I: Starting Thread3 at priority 1                                               
I: M9 T3 mirq 5511 disp 26613446 proc 61037 real 61194                          
I: M10 T3 mirq 5511 disp 27355502 proc 81129 real 81462                         
I: M13 T3 mirq 5511 disp 28013585 proc 49696 real 49934                         
I: M15 T3 mirq 5511 disp 28742139 proc 26391 real 27414                         
I: M21 T3 mirq 5511 disp 29227168 proc 67272 real 67950                         
I: M22 T3 mirq 5511 disp 30024729 proc 69360 real 70202                         
I: M25 T3 mirq 5510 disp 30705556 proc 78391 real 79210                         
I: M31 T3 mirq 5517 disp 31191378 proc 9559 real 10524                          
I: M36 T3 mirq 5511 disp 31711770 proc 2530 real 3768                           
I:         ---------- Latency (cyc) ----------                                  
I:             Best    Worst     Mean    Stdev                                  
I: MetaIRQ     5510     5630     5515       18                                  
I: Thread0  8184689 11140378  9699098   889141                                  
I: Thread1     9394  4902958  2267099  1535028                                  
I: Thread2 14794816 23133778 18985519  2549205                                  
I: Thread3 26613446 31711770 29287253  1662104                                  
I: MetaIRQ Test Complete                                                        
I: M40 T2 mirq 4061 disp 46341121 proc 32105 real 33044

Result for twister run:

myown@myown:~/zephyrproject/zephyr$ ./scripts/twister --test samples/kernel/metairq_dispatch/sample.kernel.metairq_dispatch -p nucleo_g474re --device-testing --device-serial /dev/ttyACM0
ZEPHYR_BASE unset, using "/home/myown/zephyrproject/zephyr"
Renaming output directory to /home/myown/zephyrproject/zephyr/twister-out.2
INFO    - Zephyr version: zephyr-v2.6.0-770-gbf3c6e7ba415
INFO    - JOBS: 4
INFO    - Using 'zephyr' toolchain.
INFO    - Building initial testcase list...
INFO    - 1 test scenarios (1 configurations) selected, 0 configurations discarded due to filters.

Device testing on:

| Platform      | ID   | Serial device   |
|---------------|------|-----------------|
| nucleo_g474re |      | /dev/ttyACM0    |

INFO    - Adding tasks to the queue...
INFO    - Added initial list of jobs to queue
INFO    - Total complete:    1/   1  100%  skipped:    0, failed:    0
INFO    - 1 of 1 test configurations passed (100.00%), 0 failed, 0 skipped with 0 warnings in 24.23 seconds
INFO    - In total 1 test cases were executed, 0 skipped on 1 out of total 374 platforms (0.27%)
INFO    - 1 test configurations executed on platforms, 0 test configurations were only built.

Hardware distribution summary:

| Board         | ID   |   Counter |
|---------------|------|-----------|
| nucleo_g474re |      |         1 |
INFO    - Saving reports...
INFO    - Writing xunit report /home/myown/zephyrproject/zephyr/twister-out/twister.xml...
INFO    - Writing xunit report /home/myown/zephyrproject/zephyr/twister-out/twister_report.xml...
INFO    - Run completed

@erwango
Copy link
Member

erwango commented Jul 9, 2021

@affrinpinhero-2356 This problem was showing up from time to time during month of May, but it seems that has been several weeks w/o reproduction. Thanks for the test. Let's close it for now

@erwango erwango closed this as completed Jul 9, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@FRASTM FRASTM

Labels
bug The issue is a bug, or the PR is fixing a bug platform: STM32 ST Micro STM32 priority: low Low impact/importance bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@galak @erwango @FRASTM @affrinpinhero-2356