RomRaider 0.5.4b RC1

dschultz · **Posted:** Wed Jan 04, 2012 6:36 pm

If it's a bug post it here. If you just need help setting up, sorting out your connection then start your own thread in the troubleshooting forum.

matze · **Posted:** Thu Jan 05, 2012 5:02 pm

I've got problems with the logger function: The time value isn't monotonic.

Sometimes the time value drops down randomly during long logs (20mins or so).

- this disturbs logfile display/analysis.
- if this happens the realtime graph output suspends
- the graph output will restart when the time value has reached an already displayed time sample again (I guess).

Logging otherwise continues normally.

Examples:

1)
...
491431ms
252594ms
...

2)
...
268625ms
146063ms
...

3)
...
1059200ms
842813ms
...

Cheers
matze

dschultz · **Posted:** Fri Jan 06, 2012 12:29 am

A log of this would help and if you can put the Logger in Trace mode and submit the rr_system.log when this happens that would help too.

matze · **Posted:** Fri Jan 06, 2012 3:08 pm

I've attached two logfiles and a picture.

Example 2 shows the backflip in time.

Example 4 shows three data samples with the same timestamp. This behaviour occurs quite often but most of the time with two data points only.
Maybe that's related to the first problem.

I'll post the syslog if it happens again.

matze · **Posted:** Fri Jan 06, 2012 3:28 pm

On behalf the interface speed I tested both interfaces (OP2.0, VAG K-Line) with both polling methods and the same 11 Parameters:

K-Line - slow polling: 5,26queries/s
OP2.0 - slow polling: 5,65queries/s

K-Line - fast polling: 16,30queries/s
OP2.0 - fast polling: 20,81queries/s

In all cases I let the queries/s settle.

dschultz · **Posted:** Fri Jan 06, 2012 5:20 pm

matze wrote:

I've attached two logfiles and a picture.

Example 2 shows the backflip in time.

Example 4 shows three data samples with the same timestamp. This behaviour occurs quite often but most of the time with two data points only.
Maybe that's related to the first problem.

I'll post the syslog if it happens again.

Does it do it both for the OP2 and the VAG-COM?

I noticed that your logs are missing the column heading: Time (msec),
Did you remove the (msec) part?

I also see that you appear to use COM22 for the OP2 in your pictures. Are you using the old version of the EcuFlash/OP2 software that still installs a COM port? the latest version does not have any COM associated with it and uses the J2534 interface only.

What is your OS and Java versions?

Here's a log that I have from a drive. Can you look into it to see if the same time problems pop up?

matze · **Posted:** Sat Jan 07, 2012 3:54 pm

>Does it do it both for the OP2 and the VAG-COM?
I don't know since I still have massive problems with ECU reconnects with the OP2.0 while the car runs.
I think in the end it has been unstable even without the car running.
Unfortunately changing the USB cable for an expensive Belkin double shielded one did not improve stability at all.
Running on batteries or power supply makes no difference (hence no ground loop but maybe EMI).
So atm I'm stuck to the VAG-COM.

>I noticed that your logs are missing the column heading: Time (msec),
>Did you remove the (msec) part?
yes I did (see posts above)

>What is your OS and Java versions?
WinXP Prof SP3
JAVA 6 SE update 29,
RomRaider tells: java.version=1.6.0_29
Laptop is IBM T60 1.8GHz Core Duo and dedicated ATI-X1400 graphics

>I also see that you appear to use COM22 for the OP2 in your pictures.
COM22 and 23 are bluetooth devices which aren't used but appear on the drop down list.
Other com ports are:
COM1 - a regular COM-Port.
COM3 - the modem.
COM18 - the VAG-COM.
RomRaider connects to the OP2.0 regardless of the COM-Setting.

>Are you using the old version of the EcuFlash/OP2 software that still installs a COM port?
>the latest version does not have any COM associated with it and uses the J2534 interface only.
I deinstalled everything Tactrix related and installed the latest beta (EcuFlash Version 1.43.3150).
ECUFlash prints the driver version as:
J2534 API Version: 04.04
J2534 DLL Version: 1.00.3147 Sep 3 2010 00:11:07
OP2.0 Device Firmware Version: 1.11.3137

Nonetheless I'm not shure if everything is clean:
When pulgged in Microsoft Device Manager tells:
Vehicle PassThru Interfaces/Tactrix OpenPort 2.0 (COM19).
Driver Date: 2/17/2010
Driver Version: 1.0.0.2843
But COM19 is not shown in the Logger COM-port drop down list.
As you mentioned, the new driver should no longer offer a COM-port.

But the Microsoft Software manager shows some entrys for CDM-Drivers (see pic)
which indicate that there are instances of the older drivers again!?
Do I need to and how can I get rid of them completely?

> Here's a log that I have from a drive. Can you look into it to see if the same time problems pop up?
No problems found. Haven't found a single occurrence. Your log looks smooth.
Also jitter in my logs is rather high. Especially if compared to yours.

matze · **Posted:** Sat Jan 07, 2012 4:08 pm

I've been able to reproduce the problem while traceing.

here's part of the logfile (romraiderlog_20120106_184840_backflip.csv):

Code:

...
1064094,0.00,14.16,86,2129,0.00,32.00,0.00,-0.780,1.38,0.42
1064157,0.00,14.08,86,2130,0.00,32.00,0.00,-0.780,1.38,0.42
1064203,0.00,14.16,86,2126,0.00,32.00,0.00,-0.780,1.38,0.42
1064250,0.00,14.16,86,2122,0.00,32.00,0.00,-0.780,1.36,0.42
1064297,0.00,14.16,86,2126,0.00,32.00,0.00,-0.790,1.36,0.42
1064344,0.00,14.08,86,2120,0.00,32.00,0.00,-0.790,1.32,0.42
617594,0.00,14.16,86,2124,0.00,32.00,0.00,-0.790,1.36,0.42
617641,0.00,14.16,86,2112,0.00,32.00,0.00,-0.790,1.36,0.42
617641,0.00,14.16,86,2117,0.00,32.00,0.00,-0.790,1.36,0.42
617641,0.00,14.08,86,2116,0.00,32.00,0.00,-0.790,1.34,0.42
617657,0.00,14.08,86,2099,0.00,32.00,0.00,-0.790,1.36,0.42
617657,0.00,14.08,86,2094,0.00,32.00,0.00,-0.790,1.34,0.42
617657,0.00,14.08,86,2108,0.00,32.00,0.00,-0.790,1.36,0.42
617657,0.00,14.16,86,2106,0.00,32.00,0.00,-0.790,1.34,0.42
617657,0.00,14.16,86,2115,0.00,32.00,0.00,-0.790,1.38,0.42
617657,0.00,14.08,86,2118,0.00,32.00,0.00,-0.790,1.36,0.42
617672,0.00,14.08,86,2116,0.00,32.00,0.00,-0.790,1.38,0.42
617672,0.00,14.16,86,2108,0.00,32.00,0.00,-0.790,1.38,0.42
617672,0.00,14.16,86,2094,0.00,32.00,0.00,-0.790,1.36,0.42
617672,0.00,14.16,86,2088,0.00,32.00,0.00,-0.790,1.38,0.42
...

Even the rr_system_02.log shows an anomaly (@1108953):

Code:

...
1108953 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080452193D87C
1109015 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080452193D87C
1109078 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080452171D85A
1109109 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B08045217BD864
1109172 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080442180D868
1109218 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B08044217BD863
1109297 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080442171D859
1109328 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B080442185D86D
1109390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B18044214DD836
1109453 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B08044215E9806
1109500 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B0804421599801
1109562 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B180452151D83B
1109609 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B18045214598EF
1109672 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B08045214AD833
1109718 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B18045213798E1
1109765 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3280C0150000B180442128D811
1109812 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180442137D81F
1109859 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B08042212198C6
1109937 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180442132D81A
663109 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B08043211198B7
663109 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180442115D8FD
663109 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180442100D8E8
663125 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B08044211A98C1
663125 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B080452111D8F9
663140 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804520EFD8D7
663140 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18045210CD8F5
663140 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804320EAD8D0
663140 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B0804420EFD8D5
663140 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B0804320B7D89C
663156 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B0804420CCD8B2
663156 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804420B9D8A0
663172 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804520A2D88A
663203 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804520CCD8B4
663203 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804320B7D89D
663203 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804420A6D88D
663218 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B1804320A6D88C
663218 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B0804420A4984A
663218 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18045208FD877
663234 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18046207FD868
663234 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180452094983C
663234 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18045207FD867
663265 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180452084982C
663265 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18045206FD857
663265 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B18045207AD862
...
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180441FD5D8BB
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180451FD1D8B8
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180441FBFD8A5
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B180431FA9D88E
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B080441FB2D897
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B080441F8DD872
663390 DEBUG [Thread-5] - Mode:1 ECU Response <--- 80F0100EE87E3180C0150000B080441F96983B
...

Interestingly before the time step occurs the last timestamps are strictly monotonic.
Afterwards timestamps do not increment strictly monotonic anymore.
And the delta has changed.
Before the time leap the timestamps increase in about 50ms intervalls.
Afterwards deltas are 15ms, 16ms, 14ms. As if some lower bits are missing.
Maybe a bunch of messages has build up and have to be processed at maximum speed.
Strange.

There's another thing I observed while debugging.
While fast logging 10 or more parameters, debugging romraider and graphing 3 values fullscreen (nearly) there seems to be much load on my system (50% or so).
When in this situation disk writes are suspended by the shock detection / head crash prevention process on my laptop romraider seems to freeze
until writes are enabled again. Are debug writes direct writes (not cached) which block the whole process?

dschultz · **Posted:** Sat Jan 07, 2012 4:13 pm

I really don't know what else to say. I run the same OS and slightly old Java version. Here's a shot of my devices for reference.

Attachment:

op2.png

dschultz · **Posted:** Sat Jan 07, 2012 4:28 pm

matze wrote:

I've been able to reproduce the problem while traceing.

There's another thing I observed while debugging.
While fast logging 10 or more parameters, debugging romraider and graphing 3 values fullscreen (nearly) there seems to be much load on my system (50% or so).
When in this situation disk writes are suspended by the shock detection / head crash prevention process on my laptop romraider seems to freeze
until writes are enabled again. Are debug writes direct writes (not cached) which block the whole process?

The data log file and system log file are two completely separate processes. Data logging is performed using the Java class BufferedOutputStream while the system logging is handled by the log4j class (written by Apache and claimed to be extremely efficient). The clock is obviously the same for both and is based on the computer.
With Debug trace set to Info, and saving the data log to a USB drive do you experience the same problem?

As for the CPU, I have not really benchmarked the various options. Fast poll does push CPU up a bit as there is much more serial port polling occurring with the VAG-COM. The OP2 is more efficient so CPU should be less using it. The graphics system to display and update the graphs for fast polling may definitely push up the CPU.

matze · **Posted:** Sat Jan 07, 2012 4:37 pm

hm, same properties here. Just the device has "(COM19)" instead of "J2534 Vehicle Interface"

matze · **Posted:** Sat Jan 07, 2012 4:40 pm

Good idea. Will give the USB drive a test drive.
An SSD still sits on my shelf to replace the HDD :cry:

I think this debug code will do direct writes as one wants the debug info hit the disk as fast as possible
in an effort to have the latest info just short before a crash.

dschultz · **Posted:** Sat Jan 07, 2012 5:08 pm

Debug info use log4j so it's all in the same Apache framework. It is buffered and written when time permits.

matze · **Posted:** Sat Jan 07, 2012 9:57 pm

So log4j is configured (nonstandard): immediateFlush=false and bufferedIO=true
resulting in an 8K buffer?

http://fredpuls.com/site/softwaredevelo ... e_tips.htm

Driving the HDD in park position is in the order of seconds (or as long as significant vibration is observed).
So 8K seems not that much in fast polling mode.
However I don't know how much additional buffering WinXP does before blocking a thread because of an unresponsive HDD.

Would be interesting to see if using asyncAppender=true (that yields a wopping 1MB buffer?) could help here.

dschultz · **Posted:** Sat Jan 07, 2012 11:30 pm

Changing anything with log4j only affects the rr_system.log, it has nothing to do with your data logs (.csv). So if you set the Debug mode to Info there should be minimal logging of RomRaider Logger events and all the attention will be on writing your data log. So back to the other question, want happens when you log to USB drive with Debug logging at a minimum?

RomRaider

Forum rules

RomRaider 0.5.4b RC1

Who is online