Bug #641
Does bag-play respect original timing?
| Status: | Resolved | Start date: | 10/17/2011 | |
|---|---|---|---|---|
| Priority: | High | Due date: | ||
| Assignee: | J. Moringen | % Done: | 100% | |
| Category: | - | |||
| Target version: | Robotics Service Bus - 0.5 |
Description
The attached file was recorded with about 100Hz. On the machine here, it plays back much slower with about 45Hz. I've attached the corresponding file for reference. Can anyone reproduce 100Hz on replay?
Associated revisions
fixes #641
- src/transform/rsb-event.lisp (decode rsb-event simple-array): clear
user-infos and user-times slots of the reused data-holder; otherwise
stuff will accumulate and cause horrible slowdowns
refs #641
- src/rsb/replay/delay-correcting-mixin.lisp: new file; contains
`delay-correcting-mixin' mixin class - src/rsb/replay/recorded-timing.lisp (recorded-timing): added
superclass `delay-correcting-mixin' - src/rsb/replay/fixed-rate.lisp (fixed-rate): likewise
- src/rsb/replay/package.lisp (package rsbag.rsb.replay): added
exported symbols delay-correcting-mixin, strategy-previous-call and
strategy-previous-delay - cl-rsbag.asd (system cl-rsbag): added file
src/rsb/replay/delay-correcting-mixin.lisp
refs #641
- src/rsb/replay/timed-replay-mixin.lisp (timed-replay-mixin): removed
superclass `speed-adjustment-mixin' - src/rsb/replay/recorded-timing.lisp (recorded-timing): added
superclass `speed-adjustment-mixin' - src/rsb/replay/fixed-rate.lisp (fixed-rate): likewise
History
#1 Updated by S. Wrede over 12 years ago
- Status changed from New to Feedback
Just tested it on my Mac:
With the file attached to this post, I get after a few seconds the following results which then more or less stay constant:
2011-Oct-17 17:32:29.042475|9400049886.76 ±231693.06| 21 Hz| 2011-Oct-17 17:32:30.044729|9400793046.30 ±215312.11| 23 Hz| 2011-Oct-17 17:32:31.045339|9401554429.61 ±221614.16| 23 Hz| 2011-Oct-17 17:32:32.047289|9402329482.65 ±224649.75| 23 Hz| 2011-Oct-17 17:32:33.048258|9403096778.47 ±279264.77| 15 Hz| 2011-Oct-17 17:32:34.048644|9403967367.43 ±220907.03| 21 Hz| 2011-Oct-17 17:32:35.049494|9404750478.32 ±227878.41| 19 Hz| 2011-Oct-17 17:32:36.050255|9405659716.31 ±220366.45| 16 Hz| 2011-Oct-17 17:32:37.050752|9406385993.00 ±236775.59| 20 Hz| 2011-Oct-17 17:32:38.051344|9407215164.50 ±233704.64| 20 Hz|
However, what I also just became aware of is that bag-info displayed a frequency value of 13. I doubt that this was true for the recorded data. I need to check this again.
#2 Updated by J. Moringen over 12 years ago
If the issue is urgent, please call flier.
#3 Updated by J. Moringen over 12 years ago
- Tracker changed from Support to Bug
- Project changed from Robotics Service Bus to RSBag
- Category deleted (
Common Lisp Tools) - Status changed from Feedback to In Progress
#4 Updated by J. Moringen over 12 years ago
The recorded data seems to be OK. Here are 100 differences between successive create timestamps from near the end of the recording:
RSBAG> (with-bag (bag "/tmp/WalkFourLegsCCA2.tide")
(let ((chan (first (bag-channels bag))))
(iter (for e1 each chan :from 30000 :to 30100)
(for e2 each chan :from 30001 :to 30101)
(collect (local-time:timestamp-difference
(rsb:timestamp e2 :create)
(rsb:timestamp e1 :create))))))
(0.010299d0 0.009938d0 0.010236d0 0.010066d0 0.010166d0 0.010113d0 0.010246d0
0.010037d0 0.010095d0 0.010207d0 0.010105d0 0.01021d0 0.010115d0 0.010314d0
0.009882d0 0.010236d0 0.010219d0 0.010756d0 0.009527d0 0.010162d0 0.010111d0
0.010163d0 0.010155d0 0.010097d0 0.01017d0 0.010157d0 0.010235d0 0.009964d0
0.010232d0 0.01006d0 0.010301d0 0.01008d0 0.010275d0 0.010024d0 0.010094d0
0.01021d0 0.010088d0 0.010191d0 0.010128d0 0.010162d0 0.010076d0 0.010205d0
0.010096d0 0.010364d0 0.009929d0 0.010181d0 0.010138d0 0.010021d0 0.010146d0
0.01013d0 0.010169d0 0.010082d0 0.010229d0 0.01012d0 0.010147d0 0.01012d0
0.010136d0 0.010139d0 0.01042d0 0.00978d0 0.01016d0 0.010094d0 0.010167d0
0.010128d0 0.010172d0 0.010221d0 0.010002d0 0.010195d0 0.010106d0 0.010179d0
0.010067d0 0.010257d0 0.010028d0 0.010185d0 0.0101d0 0.010139d0 0.010109d0
0.010251d0 0.010059d0 0.010132d0 0.01018d0 0.010143d0 0.01035d0 0.01025d0
0.010145d0 0.010129d0 0.010215d0 0.010136d0 0.012665d0 0.010539d0 0.010008d0
0.009808d0 0.010183d0 0.010081d0 0.010193d0 0.011656d0 0.010122d0 0.010168d0
0.010122d0 0.010141d0)
#5 Updated by J. Moringen over 12 years ago
Turns out, an optimization in cl-rsbag had gone very wrong: a pb data-holder was reused in every deserialization operation (you know where this is going, right?). Failing to clear certain fields of the data-holder between subsequent deserializations caused it to accumulate every single meta-data item decoded so far. So at the end of the file, containing roughly 30.000 events, 30.000 meta-data items would be decoded for every single event. No wonder the replay got a little slow in the end. lol.
#6 Updated by J. Moringen over 12 years ago
- Status changed from In Progress to Resolved
- % Done changed from 0 to 100
Applied in changeset r197.
#7 Updated by J. Moringen over 12 years ago
For good measure, I added an adaptive delay computation in r198. This should make the replay timing relatively faithful, even on loaded systems.
#8 Updated by J. Moringen over 12 years ago
- Artificially speed up the replay:
./bag-play -r 'recorded-timing :speed 1.3' /tmp/WalkFourLegsCCA2.tide - Force a fixed rate:
./bag-play -r 'fixed-rate :rate 1000' /tmp/WalkFourLegsCCA2.tide - Disable the progress display if the terminal causes a slowdown:
./bag-play -p none /tmp/WalkFourLegsCCA2.tide