ROS time synchronization between UE4 and ROS core about rosintegration HOT 16 CLOSED

@samkys I tested this fix yesterday and it solved the issue. The time is now clocking properly and the bag file shows the correct passage of time. Thanks so much for providing the fix and for explaining about the different tick levels.

from rosintegration.

@lthierbach Good news, I have found something that hopefully fixes the issue. Can you test it for me as well?

UE4 has different tick types. So in the file ROSIntegrationGameInstance.cpp function call:

void UROSIntegrationGameInstance::OnWorldTickStart(ELevelTick TickType, float DeltaTime)

"Ticks" with different types. https://docs.unrealengine.com/en-US/API/Runtime/Engine/Engine/ELevelTick/index.html

If you print the tick type and the DeltaTime you should find why the time runs twice as fast. So add the print.

if (bSimulateTime)
{
  FApp::SetFixedDeltaTime(FixedUpdateInterval);
  FApp::SetUseFixedTimeStep(bUseFixedUpdateInterval);

  FROSTime now = FROSTime::Now();

  //-------- Add this print line to your code. --------//
  UE_LOG(LogROS, Warning, TEXT("now._NSec: %d TickType: %d DeltaTime: %f"),now._NSec,(int)TickType,DeltaTime);

What you will see in the Output Log of PIE in UE4 is:

LogROS: Warning: now._NSec: 135014868 TickType: 0 DeltaTime: 0.113329  
LogROS: Warning: now._NSec: 248343772 TickType: 2 DeltaTime: 0.113329  
LogROS: Warning: now._NSec: 361672676 TickType: 0 DeltaTime: 0.113468  
LogROS: Warning: now._NSec: 475140476 TickType: 2 DeltaTime: 0.113468  

Notice the the tick type of 0 and 2 the time is identical, so the advancement of the simulation time runs twice as fast.

From https://docs.unrealengine.com/en-US/API/Runtime/Engine/Engine/ELevelTick/index.html you see that the tick type of 2 is for all types.

enum ELevelTick
{
    LEVELTICK_TimeOnly         = 0,
    LEVELTICK_ViewportsOnly    = 1,
    LEVELTICK_All              = 2,
    LEVELTICK_PauseTick        = 3,
}

My proposed fix that I want you to test is this:

        // Make sure we only care about the LEVELTICK_TimeOnly since we are updating time 
	if (bSimulateTime && TickType == ELevelTick::LEVELTICK_TimeOnly)
	{
		FApp::SetFixedDeltaTime(FixedUpdateInterval);
		FApp::SetUseFixedTimeStep(bUseFixedUpdateInterval);

This appears to work on my end but I want somebody else to test it. FYI to compile this delete the binaries in ROSIntegration and rebuild the project in order to make sure it re-compiles completely.

Let me know what you find out, I hope this is the fix as I need it to work as well.

from rosintegration.

setting use_sim_time=true means that the clock topic is published by one node (e.g. rosbag play). In case of ROSIntegration Plugin you can let is simulate the clock time. All other nodes usually use this time then instead of the machines clock. There is also the option to use a fixed time step so that even in case of slowing down you can be sure the clock is always published at the simulated speed you want it to. But this also means, that if UE4 is able to simulate faster than the fixed inverval you set, it runs faster than "real-time".

from rosintegration.

Ok, thanks for the feedback! I'm just struggling to get this to work "properly" so everything runs at the same pace. Ideally I would like UE4 simulation clock/frame rate be the driver of the ROS /clock topic. If you have any feedback to do this I would like to know.

Also, I will be working on this for a while and likewise if I find something will post here.

from rosintegration.

Edited
What exactly does this do in ROSTime.cpp:

void FROSTime::SetUseSimTime(bool bUseSimTime)
{
ROSTime::use_sim_time = bUseSimTime;
}

I see the obvious part a few lines above when we call the now():

if (ROSTime::use_sim_time) {
return FROSTime(ROSTime::sim_time.sec_, ROSTime::sim_time.nsec_);
}~

If true or false the topic /clock in ROS is published by /rosbridge_tcp. If true the time on /clock is running extremely fast, about 3 times normal speed. What causes this? I guess I am confused by the purpose of setting ROSTime::use_sim_time = bUseSimTime; if the /clock topic is published in both instances. My understanding of setting use_sim_time was a stated above by @Hemofektik ?

If ROSTime::use_sim_time is set to false, and on the ROS side set param use_sim_time true so /clock is published by /rosbridge_tcp at normal speed I get errors that ROS time moved backwards: 0.0xxxxx

Do we need to manually publish to the /clock topic from UE4 or can we rely on /rosbridge_tcp doing a good enough job?

from rosintegration.

Ok, I have been digging around a lot more. Found a culprit to the time jump, one of the functions ROSIntegrationGameInstance.cpp appears to not be thread safe.

void UROSIntegrationGameInstance::OnWorldTickStart(ELevelTick TickType, float DeltaTime)

This appears to be called by two instances which in turn one writes the data and then the other writes with older data.

To reproduce this error

Make sure simulate Time check box is checked in the ROSIntegrationInstance.
Then in the function above add this to the code and recompile the Plugin.** (Add it at line 161), warning: it prints a ton of information to the output console.

UE_LOG(LogROS, Warning, TEXT("now._NSec: %d nanoseconds_only: %d TickType: %d "),now._NSec,nanoseconds_only,(int)TickType);

This prints out:

1. LogROS: Warning: now._NSec: 181819530 nanoseconds_only: 23952228 TickType: 0
2. LogROS: Warning: now._NSec: 182080037 nanoseconds_only: 23952228 TickType: 2
3. LogROS: Warning: now._NSec: 181724580 nanoseconds_only: 11905503 TickType: 0

Notice from line 1->2 Forward in time. Line 2->3 Backward in time. Also notice the tick type, from 0->2->0 where the discrepancy occurred.

On the machine running ROS run the following python script which just prints out if a jump in time occurred, this is basic code and not made to be perfect but to test the system. Then you can match the time frame plotted in ROS and the game.

(Just convert to be .py as I cannot attach a .py file.)
clocker.txt

from rosintegration.

Current work around that I implemented for anyone interested:
In my ROS publisher actor I created under the
protected:
void OnWorldTickStart(ELevelTick TickType, float DeltaTime);
then in cpp:

void AROS_actor::BeginPlay()
{
	Super::BeginPlay();
	FROSTime originalTime = FROSTime::Now();
	
	// Make sure our system clock keeps clicking along
	FROSTime::SetUseSimTime(false);
	FWorldDelegates::OnWorldTickStart.AddUObject(this, &AROS_actor::OnWorldTickStart);
	
	
	UROSIntegrationGameInstance* rosinst = Cast<UROSIntegrationGameInstance>(GetGameInstance());
	ClockTopic = NewObject<UTopic>(UTopic::StaticClass());
	ClockTopic->Init(rosinst->ROSIntegrationCore, FString(TEXT("/clock")), FString(TEXT("rosgraph_msgs/Clock")), 3);

	ClockTopic->Advertise();
}

void AROS_actor::OnWorldTickStart(ELevelTick TickType, float DeltaTime)
{
		FROSTime now = FROSTime::Now();

		// send /clock topic to let everyone know what time it is...
		TSharedPtr<ROSMessages::rosgraph_msgs::Clock> ClockMessage(new ROSMessages::rosgraph_msgs::Clock(now));
		ClockTopic->Publish(ClockMessage);
}```

from rosintegration.

Interesting. I never encountered this issue. Are you testing this in PIE something similar? If so, it should be possible to distinguish between them and only publish one of them. This is definitely a bug and should be fixed. Thanks for digging that deep!

from rosintegration.

I was just testing using UE4 and launching the project while slowly stepping through each piece adding debug print statements until I found what I wrote above. What do you mean by PIE?

Also its a great project you all have going on so if I can help move it forward I will try. Let me know if you do or do not see similar errors.

from rosintegration.

I have run into what I believe to be the same problem. I am running in PIE and have set a custom time step in Unreal. The OnWorldTickStart function in ROSIntegrationGameInstance is being called twice for every Unreal tick, thus the time getting written out to the clock message is advancing twice as fast (I tested this by looking at the times recorded in a ROS bag).

from rosintegration.

@lthierbach do you have blueprints and c++ code? Just curious if that has anything to do with it? We switched mainly to c++ and am not seeing the problem yet. I still don't know what caused it...

from rosintegration.

Just read your comment again. We actually were having a different problem initially, the time would step forward then backward randomly. It does still seem the clock is running fast as you say, I will test and see if the clock is running fast and report back.

from rosintegration.

Thanks for getting back to me. We attempt to do as much in C++ as possible, but there are a few blueprints. When I put a log statement in OnWorldTickStart in ROSIntegrationGameInstance, I can clearly see it is being called twice on every tic. I confirmed it with looking at the time in the rosbag and it was double what it should be.

from rosintegration.

Finally have a little time to focus on this, hopefully I can have some meaningful results. Will try to update as I learn things.

from rosintegration.

@samkys Great, should be able to test this today or tomorrow. I will let you know.

from rosintegration.

Great! Going to close this issue then.

from rosintegration.