Bug #835

Wrong timing when replaying

Added by Anonymous over 9 years ago. Updated over 9 years ago.

Status:RejectedStart date:02/01/2012
Priority:HighDue date:
Assignee:J. Moringen% Done:

0%

Category:-
Target version:-

Description

I recorded RSB communication on 9 different channels with 200Hz events each.
Replaying seems to replay the same data, but with timing completely off. RSB Scope Monitor showed 200Hz on each channel during recording, Monitor during replaying shows changing between 0Hz and ~400-500Hz.

Don`t know if recording or replaying went wrong. Tested with bag-record and bag-play trunk, as downloaded from toolkit. (file attaching doesn`t seem to work)

History

#1 Updated by J. Moringen over 9 years ago

  • Status changed from New to In Progress
  • Assignee set to J. Moringen

I cannot properly reproduce the problem with trunk versions of bag-cat and logger using either the Spread transport or the TCP-based transport. Both transports show some jitter but not to the extend you describe (see logger output below). I could not observe extreme scope-specific jitter in C++ logger's monitor mode either.

Some observations:
  • I used the C++ and CL loggers simultaneously - this may have increased load and thus potentially jitter (especially for the TCP-based transport)
  • Spread seems to be worse in this regard
  • Is it possible, that some informers start at ~ 10 seconds into the recording? The rate seems to go up from 1400 Hz to 1800 Hz at that point

TCP example

Now                             |Rate        |Throughput      |Latency         
2012-02-01T12:54:48.257888+01:00|         N/A|           0.000|       N/A ± N/A
2012-02-01T12:54:49.257648+01:00|     892.187|        5352.830|…387.760 ± 0.017
2012-02-01T12:54:50.257624+01:00|    1400.025|        8399.866|…387.749 ± 0.004
2012-02-01T12:54:51.258099+01:00|    1400.347|        8401.766|…387.759 ± 0.013
2012-02-01T12:54:52.265621+01:00|    1382.645|        8295.650|…387.752 ± 0.012
2012-02-01T12:54:53.257849+01:00|    1418.099|        8508.545|…387.748 ± 0.002
2012-02-01T12:54:54.258371+01:00|    1400.304|        8401.656|…387.749 ± 0.002
2012-02-01T12:54:55.257696+01:00|    1399.977|        8399.880|…387.748 ± 0.001
2012-02-01T12:54:56.258130+01:00|    1399.423|        8396.398|…387.751 ± 0.008
2012-02-01T12:54:57.257569+01:00|    1667.946|       10007.224|…387.748 ± 0.002
2012-02-01T12:54:58.258134+01:00|    1801.047|       10806.186|…387.749 ± 0.003
2012-02-01T12:54:59.257713+01:00|    1800.805|       10804.278|…387.754 ± 0.011
2012-02-01T12:55:00.257373+01:00|    1798.646|       10791.907|…387.749 ± 0.001
2012-02-01T12:55:01.258382+01:00|    1798.266|       10789.394|…387.750 ± 0.004
2012-02-01T12:55:02.258033+01:00|    1804.657|       10827.562|…387.749 ± 0.003
2012-02-01T12:55:03.257689+01:00|    1800.677|       10804.073|…387.752 ± 0.008
2012-02-01T12:55:04.258246+01:00|    1799.011|       10793.761|…387.752 ± 0.008
2012-02-01T12:55:05.258027+01:00|    1801.467|       10808.681|…387.750 ± 0.005
2012-02-01T12:55:06.257804+01:00|    1794.513|       10766.939|…387.751 ± 0.007
2012-02-01T12:55:07.258175+01:00|    1646.434|        9878.552|…387.798 ± 0.031
2012-02-01T12:55:08.257743+01:00|    1696.706|       10180.082|…387.867 ± 0.024
2012-02-01T12:55:09.258362+01:00|    1766.942|       10601.183|…387.885 ± 0.018
2012-02-01T12:55:10.257982+01:00|    2066.880|       12401.233|…387.845 ± 0.083
2012-02-01T12:55:11.257744+01:00|    1729.500|       10376.781|…387.780 ± 0.021
2012-02-01T12:55:12.258217+01:00|    1834.176|       11004.927|…387.770 ± 0.023
2012-02-01T12:55:13.257616+01:00|    1391.924|        8351.763|…387.923 ± 0.082
2012-02-01T12:55:14.258074+01:00|    2120.952|       12724.785|…387.955 ± 0.090
2012-02-01T12:55:15.257902+01:00|    1903.375|       11420.078|…387.784 ± 0.038
2012-02-01T12:55:16.257751+01:00|    1131.287|        6787.894|…387.970 ± 0.119
2012-02-01T12:55:17.257907+01:00|    1269.853|        7619.101|…388.348 ± 0.095
2012-02-01T12:55:18.258259+01:00|    2088.167|       12528.062|…388.420 ± 0.085
2012-02-01T12:55:19.261707+01:00|    1912.461|       11474.653|…388.244 ± 0.072
2012-02-01T12:55:20.268329+01:00|    2483.576|       14900.554|…388.103 ± 0.126
2012-02-01T12:55:21.258349+01:00|    1886.945|       11321.795|…387.805 ± 0.022
2012-02-01T12:55:22.258086+01:00|    1856.579|       11139.620|…387.861 ± 0.076
2012-02-01T12:55:23.257702+01:00|    1592.690|        9556.042|…387.824 ± 0.032
2012-02-01T12:55:24.258157+01:00|    1620.282|        9721.616|…387.932 ± 0.024
2012-02-01T12:55:25.274505+01:00|    1916.638|       11499.398|…387.986 ± 0.051
2012-02-01T12:55:26.258032+01:00|    1718.426|       10310.662|…387.949 ± 0.023
2012-02-01T12:55:27.257782+01:00|    1559.479|        9356.620|…388.042 ± 0.035
2012-02-01T12:55:28.258984+01:00|    2413.054|       14477.368|…388.021 ± 0.109
2012-02-01T12:55:29.257890+01:00|    1809.042|       10854.733|…387.749 ± 0.003
2012-02-01T12:55:30.257742+01:00|    1797.318|       10783.294|…387.750 ± 0.004
2012-02-01T12:55:31.258338+01:00|    1804.951|       10829.719|…387.749 ± 0.003
2012-02-01T12:55:32.257854+01:00|    1800.906|       10804.992|…387.752 ± 0.007
2012-02-01T12:55:33.258317+01:00|    1694.361|       10166.381|…387.749 ± 0.002
2012-02-01T12:55:34.257950+01:00|     739.333|        4436.218|…387.749 ± 0.003
2012-02-01T12:55:35.258008+01:00|         N/A|           0.000|       N/A ± N/A

Spread example

Now                             |Rate        |Throughput      |Latency         
2012-02-01T12:56:53.268604+01:00|         n/a|             n/a|…508.905 ± 0.111
2012-02-01T12:56:54.267153+01:00|    1429.366|        8576.133|…508.759 ± 0.006
2012-02-01T12:56:55.267338+01:00|    1401.240|        8408.110|…508.759 ± 0.004
2012-02-01T12:56:56.267046+01:00|    1392.834|        8356.897|…508.758 ± 0.003
2012-02-01T12:56:57.266485+01:00|    1407.821|        8446.739|…508.760 ± 0.008
2012-02-01T12:56:58.267131+01:00|    1666.688|        9999.740|…508.767 ± 0.011
2012-02-01T12:56:59.267099+01:00|    1801.355|       10807.762|…508.760 ± 0.005
2012-02-01T12:57:00.266556+01:00|    1420.844|        8525.465|…508.818 ± 0.086
2012-02-01T12:57:01.266953+01:00|    1913.286|       11479.190|…508.924 ± 0.022
2012-02-01T12:57:02.266744+01:00|    2066.411|       12396.099|…508.806 ± 0.052
2012-02-01T12:57:03.266629+01:00|    1523.468|        9141.465|…508.799 ± 0.053
2012-02-01T12:57:04.267126+01:00|    1170.462|        7022.685|…509.067 ± 0.104
2012-02-01T12:57:05.266372+01:00|    1146.891|        6881.319|…509.409 ± 0.101
2012-02-01T12:57:06.266441+01:00|    1179.968|        7079.724|…509.788 ± 0.102
2012-02-01T12:57:07.266768+01:00|    1332.598|        7995.274|…510.090 ± 0.070
2012-02-01T12:57:08.267021+01:00|    1197.752|        7186.613|…510.379 ± 0.095
2012-02-01T12:57:09.267339+01:00|    1194.633|        7167.585|…510.723 ± 0.089
2012-02-01T12:57:10.266680+01:00|    1175.794|        7054.600|…511.045 ± 0.107
2012-02-01T12:57:11.266856+01:00|    1166.846|        7001.139|…511.413 ± 0.103
2012-02-01T12:57:12.267300+01:00|    1174.515|        7046.998|…511.757 ± 0.103
2012-02-01T12:57:13.266632+01:00|    1105.777|        6634.511|…512.138 ± 0.116
2012-02-01T12:57:14.266752+01:00|    1260.875|        7565.145|…512.469 ± 0.085
2012-02-01T12:57:15.267385+01:00|    1449.106|        8694.462|…512.715 ± 0.037
2012-02-01T12:57:16.266733+01:00|    1187.827|        7126.811|…513.005 ± 0.092
2012-02-01T12:57:17.266837+01:00|    1476.863|        8860.822|…513.262 ± 0.044
2012-02-01T12:57:18.267313+01:00|    1720.210|       10321.221|…513.363 ± 0.025
2012-02-01T12:57:19.266958+01:00|    1909.645|       11457.311|…513.369 ± 0.029
2012-02-01T12:57:20.266681+01:00|    2263.643|       13581.219|…513.203 ± 0.083
2012-02-01T12:57:21.266623+01:00|    1849.270|       11095.564|…513.063 ± 0.011
2012-02-01T12:57:22.267354+01:00|    1972.615|       11835.904|…512.987 ± 0.035
2012-02-01T12:57:23.267023+01:00|    2062.730|       12249.299|…512.885 ± 0.053
2012-02-01T12:57:24.266965+01:00|    2014.123|       12211.068|…512.798 ± 0.058
2012-02-01T12:57:25.266487+01:00|    2045.068|       12270.221|…512.601 ± 0.034
2012-02-01T12:57:26.267165+01:00|    1960.686|       11763.953|…512.541 ± 0.032
2012-02-01T12:57:27.267036+01:00|    2001.916|       12008.998|…512.415 ± 0.028
2012-02-01T12:57:28.266727+01:00|    2130.525|       12782.692|…512.245 ± 0.060
2012-02-01T12:57:29.266427+01:00|    1969.693|       11818.219|…512.131 ± 0.045
2012-02-01T12:57:30.267032+01:00|    1975.903|       11855.432|…512.006 ± 0.039
2012-02-01T12:57:31.267007+01:00|    1986.793|       11920.283|…511.940 ± 0.036
2012-02-01T12:57:32.267392+01:00|    2252.991|       13470.871|…511.749 ± 0.066
2012-02-01T12:57:33.267174+01:00|    2101.123|       12606.193|…511.546 ± 0.037
2012-02-01T12:57:34.267313+01:00|    2098.786|       12593.887|…511.397 ± 0.055
2012-02-01T12:57:35.267136+01:00|    1917.451|       11505.106|…511.276 ± 0.020
2012-02-01T12:57:36.266764+01:00|    2043.768|       12261.862|…511.167 ± 0.047
2012-02-01T12:57:37.266804+01:00|    1247.059|        7482.771|…510.965 ± 0.075
2012-02-01T12:57:38.267152+01:00|         N/A|           0.000|       N/A ± N/A

#2 Updated by Anonymous over 9 years ago

  • Status changed from In Progress to Rejected

Turned out to be not a rsbag problem, but caused due to the spread setup, using two spread daemons (even when replay and logger started on the same machine). Spread conf was:

Spread_Segment  225.0.1.1:4814 {
    sylvin        129.70.143.43
    mellit      129.70.143.46
}

Setup with one spread daemon had no significant delays, even when sending events between both machines.

#3 Updated by Anonymous over 9 years ago

We should think about where to document this kind of issues (regarding spread transport / other transports).

#4 Updated by S. Wrede over 9 years ago

How did the network setup loook like? All Spread daemons and nodes physically within a local network? I am asking that because the configuration was (from a Spread perspective) correct, wasn't it? So, this should work and it is still a bug.

Wrt to collecting these issues, I wonder if we can add a category in RSB that is targeted towards the different transports.

#5 Updated by S. Wrede over 9 years ago

Johannes: Is this related to the Spread problem we had with the dataset?

#6 Updated by S. Wrede over 9 years ago

@Arne, all: Probably we could move this ticket over to project:"RSBSpread" even if the transport is not fully externalized yet.

Also available in: Atom PDF