ICE service with Windows Administator rights and ICE Timers

[billg]

I have a question about running ice services with Windows Administrator rights vs. non-Administrator rights while using ICE and ICE timers. We have a ‘core’ system that runs an ice grid and ice boxes inside the IceGrid. We can start the core system with Windows Administrator privileges or with Non-Administrator privileges. We also have standalone ice applications that make direct connections (by directly specifying end points) to services in the ice boxes and direct connections between the standalone applications. One of our standalone applications runs as an Administrator and starts an ICE timer at a 5msec interval. I’ve observed when we run our core system (ice grids and ice boxes) as a Windows Administrator and the standalone application as an Administrator, the standalone application 5msec timer runs ~every 16msecs. The same is true if I change this 5msec value to 4,3,2msecs. If I change the timer value to 1msec, the timer runs every 1msec. However, if I run our core system (ice grid and ice boxes) as a non-Administrator and the standalone application as an Administrator, the standalone ICE timer runs every 5msecs (or 4, 3,2,1, etc.). I can’t find any documentation on this behavior in the documentation or forums and was wondering if this is expected or if this is something we can control? Thanks for your help.

[bernard]

Hi Bill,

We're going to try to reproduce this surprising behavior and understand what's happening. The timer in question is a C++ IceUtil::Timer object inside your standalone application?

Could you provide more details on your environment, in particular:
- your Windows version
- your Ice version (e.g. the 32-bit 3.4.1 binaries for VS2008)

Thanks,
Bernard

[billg]

Hi Bernard -

Thanks for the quick response. The timer in question is a C++ IceUtil::Timer object (I can send you code examples if you want). Windows version is Windows 7 Embedded 64-bit (Build 7601) and ICE version 3.4.1 64-bit vc10.0 libraries.

Thanks again.

-Bill

[bernard]

Hi Bill,

I tried to reproduce what you're seeing by modifying the IceGrid\icebox demo (a very simple demo). I just added a timer to the client:

class Task : public IceUtil::TimerTask
{
public:

	Task() :
	  _lastTime(IceUtil::Time::now()),
	_count(0)
	{
	}
	virtual void runTimerTask()
	{
		IceUtil::Time diff = IceUtil::Time::now() - _lastTime;
		if(_min == IceUtil::Time() || diff < _min)
		{
			_min = diff;
		}
		
		if(_max == IceUtil::Time() || diff > _max)
		{
			_max = diff;
		}

		_total += diff;

		_lastTime += diff;
		_count++;
	}

	virtual ~Task()
	{
		cerr << "Count = " << _count << endl;
		cerr << "Min = " << _min.toDuration() << endl;
		cerr << "Max = " << _max.toDuration() << endl; 
		cerr << "Avg = " << (_total / _count).toDuration() << endl;
	}

private:
	IceUtil::Time _lastTime;
	IceUtil::Time _min;
	IceUtil::Time _max;
	IceUtil::Time _total;
	int _count;
};

int
HelloClient::run(int argc, char* argv[])
{
 // ...

        IceUtil::TimerTaskPtr task = new Task;			
	IceUtil::TimerPtr timer = new IceUtil::Timer;
        timer->scheduleRepeated(task, IceUtil::Time::milliSeconds(5));
	IceUtil::ThreadControl().sleep(IceUtil::Time::seconds(30));
	timer->destroy();
// ...
}

and shockingly, got about 15 to 16 ms for each run. I also tried different periods (1ms, 10ms, 50ms), with each time an "overhead" of 10 to 12ms. Running the server part of this demo or not runningit didn't change anything. Likewise, running this code as administrator or myself didn't a difference. (I tried all this on Windows 7 x64 with VS2008 - not Windows Embedded 7 x64).

It turns out that the issue is the default clock, which is has a very poor resolution on Windows. Switching to the Monotonic clock fixed the problem:

class Task : public IceUtil::TimerTask
{
public:

	Task() :
	  _lastTime(IceUtil::Time::now(IceUtil::Time::Monotonic)),
	_count(0)
	{
	}
	virtual void runTimerTask()
	{
		IceUtil::Time diff = IceUtil::Time::now(IceUtil::Time::Monotonic) - _lastTime;
		if(_min == IceUtil::Time() || diff < _min)
		{
			_min = diff;
		}
		
		if(_max == IceUtil::Time() || diff > _max)
		{
			_max = diff;
		}

		_total += diff;

		_lastTime += diff;
		_count++;
	}

	virtual ~Task()
	{
		cerr << "Count = " << _count << endl;
		cerr << "Min = " << _min.toDuration() << endl;
		cerr << "Max = " << _max.toDuration() << endl; 
		cerr << "Avg = " << (_total / _count).toDuration() << endl;
	}

private:
	IceUtil::Time _lastTime;
	IceUtil::Time _min;
	IceUtil::Time _max;
	IceUtil::Time _total;
	int _count;
};

With Monotonic, I get the expected result (5ms for min, max and average).

With the default clock (Realtime), Ice uses ftime, while with the Monotomic clock, Ice uses the high-resolution performance counter.

Can you double-check how you measure time? And if you still get a strange result, can you attach a code sample?

Thanks,
Bernard

[billg]

Hi Bernard -

I am capturing the timer intervals using an output pin on my system and watching the pin toggle using an oscilloscope. I have re-created the timing scenarios in Admin. vs. non-Admin. many times (and did again just now). Another piece of information that might be helpful is that my standalone process (w\ Admin. priviledges) is set to REAL_TIME_PRIORITY and timer is THREAD_PRIORITY_TIME_CRITICAL - see code samples below.

// Here's how the process is setting its priority
TheProcessId = GetCurrentProcessId();
HandleToProcess = OpenProcess( PROCESS_ALL_ACCESS, false, TheProcessId );
SetPriorityClass( HandleToProcess, REALTIME_PRIORITY_CLASS );

// Here is how the timer is created
IceUtil::TimerPtr mainTimerPtr = new IOHubMainTimer();
IceUtil::TimerTaskPtr mainTimeTaskPtr = new IOHubMainTimerTask( this );
mainTimerPtr->scheduleRepeated( mainTimeTaskPtr, IceUtil::Time::milliSeconds( 5 ) );

// Timer
IOHubMainTimer::IOHubMainTimer() : Timer( THREAD_PRIORITY_TIME_CRITICAL )
{
}


IOHubMainTimerTask::IOHubMainTimerTask( HardwareImplementation * pHWImpPtr ) : TimerTask()
{
HandlePowerUp();
}


// This is the standalone task
void IOHubMainTimerTask::runTimerTask()
{

IceUtil::Mutex::Lock local_lock( m_pHWImplementation->FPGA_Mutex );


try
{

// Toggling output pin HIGH HERE for oscilloscope


switch( MainTimerTaskState )
{
case TTS_READ_CABINET_ID_DATA :
ReadCabinetIdData();
MainTimerTaskState = TTS_DO_NORMAL_PROCESSING;
break;

case TTS_DO_NORMAL_PROCESSING :
TaskTimeTickCtr++;


LookForDoorChanges();

LookAtStateOfFPGAInterface_GenerateErrorIfDetected ();
break;

}

// Toggling output pin LOW HERE for oscilloscope

}

catch( ... )
{
// Reset any necessary data, etc.
TaskTimeTickCtr = 0;

std::cerr << "Exception in IOHub Main Task Timer" << std::endl;
}

}

[bernard]

Hi Bill,

I am not sure how we can help, as replicating your environment would be very difficult.

The IceUtil::Timer implementation is straightforward: IceUtil::Timer just starts one thread (with the given priority), and then periodically calls the registered tasks. The "wait" for x ms is timedWait on a IceUtil::Monitor, which on Windows is a WaitForSingleObject on a local Semaphore.

As an experiment, you could replace this IceUtil::Timer by your own class that just starts a thread, calls your task and then sleeps for 5ms. This should be easy to do and I expect you'll see the same behavior as with the Timer.

The difference between Admin / non-Admin behavior could be related to the call to SetPriorityClass(..., REALTIME_PRIORITY_CLASS). On my Windows 7 system, when run as non-Administrator, this call succeeds but the process only gets HIGH_PRIORITY. When run as Administrator, I get REALTIME_PRIORITY as expected.

Do you have other REALTIME_PRIORITY threads (e.g. in your IceBox services) that could prevent this HIGH_PRIORITY thread from running?

Best regards,
Bernard

[billg]

Hi Bernard -

I'll see if I can re-create this in a Win 7 64 bit environment (non-Embedded), but until then let me re-state/clarify/a bit more info. on a few things that might help.

There are no other realtime priority threads in the system (the standalone process and its timer are the only ones time critical).

The core system (server) can run as Admin./non-Admin.

The standalone process always runs as Admin. (in order to get real-time priority).

When the standalone process timer is set to 1msecs, the timer *always* runs at 1msec interval regardless of if core system is Admin./non-Admin. But if core system is Admin. and standalone process is set to 2, 3, 5msec, it's always running at 16msecs. If core system runs as non-Admin., standalone process will run at 2, 3, 5 msec intervals.

I believe Windows thread/Sleep(x) time precision is always 15msecs (I tried this in past experiments, again just now in Win 7 64 Embbeded and still 15msecs - I've seen better explanations, but see Description of Performance Options in Windows for more info.) If you sleep(1) or sleep(15), the thread will run every 15msecs, sleep(16) or sleep(28) will run every 30msecs, etc.

What version of Win 7 64 are you using?

Thanks again for the help.

-Bill

[bernard]

Hi Bill,

I was testing with Windows 7 Professional x64 without service pack (I could easily install SP1 if needed). I hope you can reproduce it there.

Thanks,
Bernard

[billg]

Hi Bernard -

I've done some more experiments, still using my Win 7 64 Embedded, and have some more information and questions.

First, the issue I'm observing looks like it has nothing to do with Admin. vs non-Admin. privileges - many apologies, that's how the issue was presenting itself to me when I was testing and thought that was the source, but it appears not to be true.

I ran some more tests with just a standalone process and I'm still seeing behavior I don't understand, but my new questions are about how the IceUtil::Timer, via scheduleRepeated(), provide millisecond scheduling/timing? How do these ICE timers interact with Windows scheduler? Under Windows, I thought the time slice was 15msecs so how does the Ice timer provide timing less than 15msecs? This may explain what I'm observing.

Thanks again.
-Bill

[benoit]

Hi,

The Timer class can definitely wait for less than 15ms between executing two tasks. For the wait, it's using a monitor which ends up using the WaitForSingleObject system call This system call does allow waiting at a 1ms precision.

Cheers,
Benoit.

[billg]

Thanks Benoit. I'm going to trying to experiment with WaitForSingleObject(), but maybe you can explain what I'm seeing?

I have Windows 7, 64-bit Embedded at 'idle' (no other applications running) and I start an IceUtil::Timer at 1msec interval, the timer runs at 1msec (I'm toggling an output pin and looking at the pin using an oscilloscope). If I start other applications the timer still runs at 1msec.

Back to 'idle' (no other applications running) and now I start the timer to run at 2 (or 5)msecs the timer is running ~15-16msecs. But if I start a specific application, the timer starts running at 2 (or 5)msecs. If I stop that application, the timer goes back to ~15-16msecs. The applications I've found that change the timer are: Unigine Heaven video benchmark tool Heaven DX11 Benchmark 2.5 | Unigine (advanced 3D engine for multi-platform games and virtual reality systems) or running BurnInTest PassMark BurnInTest software - PC Reliability and Load Testing with the sound test enabled, but Unigine is better because the BurnInTest sound test isn't as consistent.

Do you have any idea why this would be happening? I can re-create this easily - a Windows issue?

Thanks.
-Bill

[bernard]

Hi Bill,

Here is an interesting article from Microsoft on timer resolution in Windows 7: Timers, Timer Resolution, and Development of Efficient Code

The default is 15.6 ms, but can be reduced to 1ms using timeBeginPeriod . The Remarks for timeBeginPeriod include:

This function affects a global Windows setting. Windows uses the lowest value (that is, highest resolution) requested by any process. Setting a higher resolution can improve the accuracy of time-out intervals in wait functions. However, it can also reduce overall system performance, because the thread scheduler switches tasks more often. High resolutions can also prevent the CPU power management system from entering power-saving modes. Setting a higher resolution does not improve the accuracy of the high-resolution performance counter.

IceUtil::Timer uses one of these "time-out intervals in wait functions", namely a time-out on WaitForSingleObject called on a simple Semaphore:

// From IceUtil/Cond.cpp

bool
IceUtilInternal::Semaphore::timedWait(const IceUtil::Time& timeout) const
{
    IceUtil::Int64 msTimeout = timeout.toMilliSeconds();
    if(msTimeout < 0 || msTimeout > 0x7FFFFFFF)
    {
        throw IceUtil::InvalidTimeoutException(__FILE__, __LINE__, timeout);
    } 

    DWORD rc = WaitForSingleObject(_sem, static_cast<DWORD>(msTimeout));
    if(rc != WAIT_TIMEOUT && rc != WAIT_OBJECT_0)
    {
        throw IceUtil::ThreadSyscallException(__FILE__, __LINE__, GetLastError());
    }
    return rc != WAIT_TIMEOUT;
}

Ice itself does not call timeBeginPeriod, or, as far as I know, any Windows function that may affect timer resolution.

You could try to call timeBeginPeriod (and later timeEndPeriod) to see if this provides a good time resolution ... for Windows timers, WaitForSingleObject on various objects and indirectly IceUtil::Timer.

Please let us know what you find.

Thanks,
Bernard

[billg]

Hi Bernard -

That's it, thanks so much. I was wondering if it was something like that as I've read about the standard 15msec timer and the high resolution timers, but thought maybe the IceUtil::Timer was keeping track/taking care of that, especially when I saw that 1msec timers always worked (Windows must set the timer automatically in that case? - interesting). And now I also see that the ICE source code is available, I'll try to do some research in the future to look at implemetation before I ask questions (many apologies).

So, all I did was add the timeBeginPeriod() call right before I started my IceUtil::Timer - everything works as expected and it all makes sense. If I call timeBeginPeriod( 2 ) and run Ice timer at 2, I get a 2msec timer, same with 5 and 5, etc.. And if I call timeBeginPeriod( 5 ), but start 2 msec timer, I only get a 5msec timer ... which is what I'd expect.

Again, many thanks for your help and patience (not too familiar w/ Windows scheduler, etc. yet but getting there).

-Bill

[bernard]

Hi Bill,

It's good to hear you figured it out.

The behavior is still not totally clear to me. For example, on my desktop, I was getting consistently the requested 5ms, measured using a Monotonic clock, itself implemented using the high-resolution performance counter (whose accuracy should not depend on timer resolution). It's possible other factors, such as power-management on the system, also affect timer resolution ... the best would be to ask Microsoft.

Best regards,
Bernard