interpreting PM performance log data?

264 views
Skip to first unread message

Andrew Chapman

unread,
Jan 29, 2014, 1:40:15 AM1/29/14
to drones-...@googlegroups.com
Hi all, could someone point me to some info on interpreting the PM log data to detect when there's a performance problem, slow loops, etc?

I'm keen to know what values would constitute a warning sign, and what is definitely a problem.

Any pointers appreciated, and bonus points for any dataflash log files exhibiting performance problems, thanks.

Randy Mackay

unread,
Jan 29, 2014, 2:33:39 AM1/29/14
to drones-...@googlegroups.com

AC,

 

     The “NLon” column holds the number of slow loops (i.e. loops that ran at least 5% slower than they should which is 10500 microseconds) and the “NLoop” col holds the total number of loops since the last PM message.  Generally we print the message every 10seconds so we get 1000 loops when running at 100hz but I expect on the Pixhawk that number will eventually be higher.  In any case, the percentage of slow loops should generally stay below 5%.  So 50 slow loops or so ok.  Above that means something is probably going wrong.

 

     The “MaxT” is the maximum time in microseconds (i.e. 1 millionth of a second) that the mainloop took.  I.e. the slowest loop over the past 10seconds took X microseconds.  With our 100hz main loop rate it should ideally take 10,000 microseconds.  If we saw numbers over 13000 I’d get worried.  The only exception is when we arm (EV 10 or 11).  In these cases we expect a very slow main loop of over 1 second.  So you could probably throw away numbers that are over 200,000 (i.e 0.2 seconds).

 

-Randy

--
You received this message because you are subscribed to the Google Groups "drones-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to drones-discus...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

Andrew Chapman

unread,
Jan 30, 2014, 4:47:14 AM1/30/14
to drones-...@googlegroups.com
Thanks Randy,

I'm ignoring the first instance of a PM line after each arm/disarm event but still finding occasional isolated instances of MaxT in the 13k-60k range. They seem a bit random so I'll leave those out of the test for now, unless you can suggest other known causes where they're expected to be large?

Checking based on NLon vs NLoop is working now though and is correctly flagging the logs from Robert's Octo performance issues a few months back:

Dataflash log analysis report for file: logs/robert_lefebvre_octo_PM.log
Log size: 0.30mb (4750 lines)
Log duration: 0:02:35

Vehicle Type: ArduCopter (octo)
Firmware Version: V3.0.1 ()
Hardware: APM 2
Free RAM: 1331


Test Results:
         Balance/Twist:  PASS                                                         
              Brownout:  PASS                                                         
               Compass:  PASS                                                         
                 Empty:  PASS                                                         
        Event/Failsafe:  FAIL       ERR found: GPS                                        [GRAPH]
                   GPS:  WARN       Min satellites: 6, Max HDop: 4.68                     [GRAPH]
            Parameters:  FAIL       Bad parameters found:                                 [GRAPH]
                           THR_MID set to 300.0, expecting less than 300
           Performance:  FAIL       14 slow loop lines found, max 18% on line 2983        [GRAPH]
            Pitch/Roll:  PASS                                                         
          Underpowered:  PASS                                                         
                   VCC:  PASS                                                         
             Vibration:  UNKNOWN    No IMU log data                                   

XML output written to file: example_output.xml

Randy Mackay

unread,
Jan 30, 2014, 6:39:50 AM1/30/14
to drones-...@googlegroups.com

Ok, sounds good.  THR_MID should can be between 300 ~ 700 I think.

 

-Randy

--

Robert Lefebvre

unread,
Jan 30, 2014, 8:04:37 AM1/30/14
to drones-discuss
Andrew, does is correctly sort through and find which of the logs I sent pass and which fail?  Because some of them should pass.


Andrew Chapman

unread,
Jan 30, 2014, 12:22:49 PM1/30/14
to drones-...@googlegroups.com
Hi Robert,

Below are the results for all the logs you sent me. 6 fail, 4 warnings, 3 pass. Is that what you're expecting?

At the moment it considers it a FAIL if any PM line has >10% slow loops or there are more than 5 PM lines > 6%. And it is a warning if any single PM line shows >6% slow loops.

Most other logs I have pass using these thresholds, and they're easy to tweak of course - do you think I should loosen it up a little so the ones here that trigger the warning pass? Maybe ignore a single instance if <10%?


Dataflash log analysis report for file: logs/robert_pm/AH_Test_10_Quad_Thr1000_No_Mount_w_Logs.log
           Performance:  PASS                                                        
Dataflash log analysis report for file: logs/robert_pm/AH_Test_11_XOcto_Thr1000_No_Mount_w_Logs.log
           Performance:  FAIL       8 slow loop lines found, max 17.74% on line 4531      [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_12_XOcto_no_Mount_Simple.log
           Performance:  FAIL       12 slow loop lines found, max 18.74% on line 3770     [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_13_XOcto_w_Mount_Simple.log
           Performance:  FAIL       12 slow loop lines found, max 15.82% on line 4598     [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_1_Quad_No_Mount.log
           Performance:  WARN       1 slow loop lines found, max 7.30% on line 4139       [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_2_Quad_w_Mount.log
           Performance:  WARN       1 slow loop lines found, max 6.90% on line 4947       [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_3_Quad_G_Dt_w_Mount.log
           Performance:  WARN       1 slow loop lines found, max 8.60% on line 6505       [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_4_Quad_ThrMax_1000.log
           Performance:  WARN       1 slow loop lines found, max 7.68% on line 2093       [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_5_XOcto_Timer_w_Mount.log
           Performance:  FAIL       14 slow loop lines found, max 18.56% on line 2983     [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_6_XOcto_02_w_Mount.log
           Performance:  FAIL       9 slow loop lines found, max 18.50% on line 2424      [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_7_XOcto_02_No_Mount.log
           Performance:  FAIL       8 slow loop lines found, max 13.79% on line 1538      [GRAPH]
Dataflash log analysis report for file: logs/robert_pm/AH_Test_8_Quad_02_Thr1000_No_Mount.log
           Performance:  PASS                                                        
Dataflash log analysis report for file: logs/robert_pm/AH_Test_9_Quad_02_Thr1000_w_Mount.log
           Performance:  PASS 

Robert Lefebvre

unread,
Jan 30, 2014, 12:29:17 PM1/30/14
to drones-discuss
That looks pretty reasonable to me.  If you notice, no quad tests failed.  And all XOcto tests failed.  And it looks like with mount it did worse on "max".  So it's about what we would expect.

This was all with 3.0.1.  I should see if I can find my Octo tests on 3.1 where we declared the problem solved, as it should show a pass, or a warn at worst.


--

Andrew Chapman

unread,
Jan 30, 2014, 9:09:48 PM1/30/14
to drones-...@googlegroups.com
Great, let me know if you have that log, I'd love to see how that shakes out

Robert Lefebvre

unread,
Jan 30, 2014, 10:00:40 PM1/30/14
to drones-discuss
I had a look, it's not obvious what's what, I didn't label those.  Sorry.

Reply all
Reply to author
Forward
0 new messages