THREAD_RETURN WINAPI bgThread4SemTest( LPVOID dum )
{ unsigned long ret;
double tEnd;
HANDLE hh;
MSEmul_UseSharedMemory(true);
hh = OpenSemaphore( DELETE|SYNCHRONIZE|SEMAPHORE_MODIFY_STATE, false, (char*)"cseSem");
if( hh ){
#if defined(__windows__)
fprintf( stderr, "##%lx bgThread4SemTest starting to wait for semaphore (0x%p) release at t=%g\n",
GetCurrentThreadId(), hh, HRTime_Time() - tStart );
#else
fprintf( stderr, "##%lx bgThread4SemTest starting to wait for semaphore (0x%p,%s,%p) release at t=%g\n",
GetCurrentThreadId(), hh, hh->d.s.name, hh->d.s.sem, HRTime_Time() - tStart );
#endif
ret = WaitForSingleObject( hh, INFINITE ); tEnd = HRTime_Time();
fprintf( stderr, "##%lx WaitForSingleObject( hh, INFINITE ) = %lu at t=%g; sleep(1ms) and ReleaseSemaphore(hh,1,NULL)\n",
GetCurrentThreadId(), ret, tEnd - tStart );
Sleep(1);
fprintf( stderr, "##%lx t=%g ReleaseSemaphore(hh,1,NULL) = %d\n",
GetCurrentThreadId(), HRTime_Time() - tStart, ReleaseSemaphore(hh, 1, NULL) );
CloseHandle(hh);
}
else{
fprintf( stderr, "##%lx bgThread4SemTest() couldn't obtain semaphore '%s', will exit\n", GetCurrentThreadId(), "cseSem" );
}
return (THREAD_RETURN)3;
}
THREAD_RETURN WINAPI bgThread2Nudge( LPVOID dum )
{ unsigned long ret;
double tEnd;
fprintf( stderr, "##%lx bgThread2Nudge starting to wait for nudge event at t=%g\n", GetCurrentThreadId(), HRTime_Time() - tStart );
ret = WaitForSingleObject( nudgeEvent, INFINITE ); tEnd = HRTime_Time();
fprintf( stderr, "##%lx WaitForSingleObject( nudgeEvent, INFINITE ) = %lu at t=%g; sleep(1ms) and then send return nudge\n", GetCurrentThreadId(), ret, tEnd - tStart );
Sleep(1);
fprintf( stderr, "##%lx t=%g SetEvent(nudgeEvent) = %d\n", GetCurrentThreadId(), HRTime_Time() - tStart, SetEvent(nudgeEvent) );
return (THREAD_RETURN)2;
}
BOOL ReceiveMessageFromNet( SOCK ss, NetMessage *msg, int timeOutMs, BOOL block, const char *caller )
{ BOOL ret = FALSE;
if( msg && ss != NULLSOCKET ){
CritSectEx::Scope scope(ReceiveMutex);
ret = BasicReceiveNetMessage( ss, msg, sizeof(NetMessage), timeOutMs, block );
if( ret ){
if( msg->size != sizeof(NetMessage) || msg->protocol != NETMESSAGE_PROTOCOL ){
QTils_LogMsgEx(
"ReceiveMessageFromNet: ignoring NetMessage with size %hu!=%hu and/or protocol %hu!=%hu",
msg->size, sizeof(NetMessage), msg->protocol, NETMESSAGE_PROTOCOL );
ret = FALSE;
receiveError();
}
#ifdef COMMTIMING
msg->recdTime = HRTime_Time();
if( msg->sentTime >= 0.0 ){
cumSendRcvDelay += msg->recdTime - msg->sentTime;
sendRcvDelays += 1;
}
#endif
}
else{
if( errSock ){
NetMessageToLogMsg( caller, "Receive error)", msg );
receiveError();
errSock = 0;
}
}
}
return ret;
}
BOOL SendMessageToNet( SOCK ss, NetMessage *msg, int timeOutMs, BOOL block, const char *caller )
{ BOOL ret = FALSE;
if( msg && ss != NULLSOCKET ){
CritSectEx::Scope scope(SendMutex);
errSock = 0;
msg->size = sizeof(*msg);
msg->protocol = NETMESSAGE_PROTOCOL;
#ifdef COMMTIMING
msg->sentTime = HRTime_Time();
msg->recdTime = -1;
#endif
ret = BasicSendNetMessage( ss, msg, sizeof(NetMessage), timeOutMs, block );
if( ret ){
NetMessageToLogMsg( caller, "(sent)", msg );
}
else{
NetMessageToLogMsg( caller, "(failure)", msg );
if( errSock ){
SendErrors += 1;
if( HandleSendErrors ){
HandleSendErrors(SendErrors);
}
}
}
}
return ret;
}
THREAD_RETURN WINAPI bgThreadSleeper( LPVOID dum )
{
fprintf( stderr, "## GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fprintf( stderr, "## GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fprintf( stderr, "## GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fprintf( stderr, "##%lx bgThreadSleeper starting to sleep for 5s at t=%g\n", GetCurrentThreadId(), HRTime_Time() - tStart );
Sleep(5000);
fprintf( stderr, "##%lx bgThreadSleeper will exit at t=%g\n", GetCurrentThreadId(), HRTime_Time() - tStart );
return (THREAD_RETURN)1;
}
int ParallelFileProcessor::run()
{ FileEntry entry;
int i, nRequested = nJobs;
double N = size(), prevPerc = 0;
if( nJobs >= 1 ){
allDoneEvent = CreateEvent( NULL, false, false, NULL );
}
for( i = 0 ; i < nJobs ; ++i ){
// workers attacking the item list rear are created last
// (not that this makes any difference except in the stats summary print out...)
bool fromRear = i >= nJobs - nReverse;
FileProcessor *thread = new FileProcessor(this, fromRear, i);
if( thread ){
threadPool.push_back(thread);
}
else{
nJobs -= 1;
}
}
if( nJobs != nRequested ){
fprintf( stderr, "Parallel processing with %ld instead of %d threads\n", nJobs, nRequested );
}
const double startTime = HRTime_Time();
for( i = 0 ; i < nJobs ; ++i ){
threadPool[i]->Start();
}
if( allDoneEvent ){
DWORD waitResult = ~WAIT_OBJECT_0;
// contrary to what one might expect, we should NOT use size()==0 as a stopping criterium.
// The queue size is decreased when a worker picks a new file to process, not when it's
// finished. Using size()==0 as a stopping criterium caused the processing interrupts
// that were observed with large files.
while( nJobs >= 1 && !quitRequested() && waitResult != WAIT_OBJECT_0 ){
if( nJobs ){
double perc = 100.0 * nProcessed / N;
if( perc >= prevPerc + 10 ){
fprintf( stderr, "%s %d%%", (prevPerc > 0)? " .." : "", int(perc + 0.5) );
if( verboseLevel > 1 ){
double avCPUUsage = 0;
for( i = 0 ; i < nJobs ; ++i ){
if( threadPool[i]->nProcessed && threadPool[i]->avCPUUsage > 0){
avCPUUsage += threadPool[i]->avCPUUsage / threadPool[i]->nProcessed;
}
}
if (avCPUUsage >= 0) {
// we report the combined, not the average CPU time, so N threads
// having run at 100% CPU will print as N00% CPU.
fprintf( stderr, " [%0.2lf%%]", avCPUUsage );
}
}
fflush(stderr);
prevPerc = perc;
}
}
waitResult = WaitForSingleObject( allDoneEvent, 2000 );
}
if( (quitRequested() && !threadPool.empty()) || nProcessing > 0 ){
// the WaitForSingleObject() call above was interrupted by the signal that
// led to quitRequested() being set and as a result the workers haven't yet
// had the chance to exit cleanly. Give them that chance now.
fprintf( stderr, " quitting [%ld]...", nProcessing ); fflush(stderr);
waitResult = WaitForSingleObject( allDoneEvent, nProcessing * 500 );
for( i = 0 ; i < nProcessing && waitResult == WAIT_TIMEOUT ; ++i ){
fprintf( stderr, " [%ld]...", nProcessing) ; fflush(stderr);
waitResult = WaitForSingleObject( allDoneEvent, nProcessing * 500 );
}
}
fputc( '\n', stderr );
CloseHandle(allDoneEvent);
allDoneEvent = NULL;
}
i = 0;
double totalUTime = 0, totalSTime = 0;
// forced verbose mode: prints out statistics even if some aren't meaningful when
// verboseLevel==0 (like compression ratios in zfsctool).
int verbose = verboseLevel;
if (getenv("VERBOSE")) {
verbose = atoi(getenv("VERBOSE"));
}
while( !threadPool.empty() ){
FileProcessor *thread = threadPool.front();
if( thread->GetExitCode() == (THREAD_RETURN)STILL_ACTIVE ){
fprintf( stderr, "Stopping worker thread #%d that is still %s!\n", i, (thread->scope)? "processing" : "active" );
std::string currentFileName = thread->currentFileName();
if( currentFileName.c_str()[0] ){
fprintf( stderr, "\tcurrent file: %s\n", currentFileName.c_str() );
}
thread->Stop(true);
}
if( thread->nProcessed ){
if( verbose ){
fprintf( stderr, "Worker thread #%d processed %ld files",
i, thread->nProcessed );
fprintf( stderr, ", %0.2lf Kb [%0.2lf Kb] -> %0.2lf Kb [%0.2lf Kb] (%0.2lf%%)",
thread->runningTotalRaw/1024.0, thread->runningTotalRaw/1024.0/thread->nProcessed,
thread->runningTotalCompressed/1024.0, thread->runningTotalCompressed/1024.0/thread->nProcessed,
100.0 * double(thread->runningTotalRaw - thread->runningTotalCompressed) / double(thread->runningTotalRaw) );
if( thread->isBackwards ){
fprintf( stderr, " [reverse]");
}
if( verbose > 1 ){
if( thread->hasInfo ){
fprintf( stderr, "\n\t%gs user + %gs system",
thread->userTime, thread->systemTime );
totalUTime += thread->userTime, totalSTime += thread->systemTime;
#ifdef __MACH__
fprintf( stderr, "; %ds slept", thread->threadInfo.sleep_time );
#elif defined(CLOCK_THREAD_CPUTIME_ID)
fprintf(stderr, " ; %gs CPU", thread->cpuTime);
#endif
const auto acu = thread->avCPUUsage / thread->nProcessed;
if (thread->avCPUUsage >= 0) {
fprintf(stderr, "; %0.2lf%%", acu);
}
if (thread->m_ThreadCtx.m_runTime > 0) {
const auto rcu = (thread->userTime + thread->systemTime) * 100.0 / thread->m_ThreadCtx.m_runTime;
if (std::fabs(rcu - acu) > 5) {
fprintf(stderr, "; %0.2lf%% real", rcu);
}
}
}
}
fputc( '\n', stderr );
}
}
delete thread;
threadPool.pop_front();
i++;
}
const double endTime = HRTime_Time();
if( verbose > 1 && (totalUTime || totalSTime)){
const double totalCPUUsage = (totalUTime + totalSTime) * 100.0 / (endTime - startTime);
fprintf(stderr, "Total %gs user + %gs system; %gs total; %0.2lf%% CPU\n",
totalUTime, totalSTime, endTime - startTime, totalCPUUsage);
}
return nProcessed;
}
int main( int argc, char *argv[] )
{ int i;
HANDLE bgThread;
DWORD exitCode;
SECURITY_ATTRIBUTES semSec;
MSEmul_UseSharedMemory(true);
#if 1
{ char test[256], *head;
test[0] = '\0';
head = test;
fprintf( stderr, "appending to test[%lu] with snprintf:\n", sizeof(test) );
do{
int len = strlen(test), n;
size_t ni = strlen("0123456789");
fprintf( stderr, "len(test[%lu])=%d, rem. %lu added", sizeof(test), len, (size_t)(sizeof(test) - len) ); fflush(stderr);
n = snprintf( &test[len], (size_t)(sizeof(test) - len), "0123456789" );
head += n;
fprintf( stderr, " %d (head[%lu]=", n, head - test ); fflush(stderr);
if( len + n < sizeof(test) ){
fprintf( stderr, "%c) -> %lu\n", head[0], strlen(test) );
}
else{
fprintf( stderr, "!$@#) -> %lu\n", strlen(test) );
}
} while( strlen(test) < sizeof(test)-1 );
fprintf( stderr, "test = %s\n", test );
}
#endif
init_HRTime();
tStart = HRTime_Time();
HRTime_tic();
{ double t0;
DWORD ret;
HANDLE hh;
if( (hh = CreateSemaphore( NULL, 1, 0x7FFFFFFF, NULL )) ){
t0 = HRTime_Time();
ret = WaitForSingleObject(hh, (DWORD)(SLEEPTIMEFG*1000));
t0 = HRTime_Time() - t0;
fprintf( stderr, "WaitForSingleObject(hh,%lu)==%lu took %g seconds\n",
(DWORD)(SLEEPTIMEFG*1000), ret, t0
);
t0 = HRTime_Time();
ret = WaitForSingleObject(hh, (DWORD)(SLEEPTIMEFG*1000));
t0 = HRTime_Time() - t0;
fprintf( stderr, "WaitForSingleObject(hh,%lu)==%lu took %g seconds\n",
(DWORD)(SLEEPTIMEFG*1000), ret, t0
);
t0 = HRTime_Time();
ret = WaitForSingleObject(hh, 500);
t0 = HRTime_Time() - t0;
fprintf( stderr, "WaitForSingleObject(hh,500)==%lu took %g seconds\n",
ret, t0
);
ReleaseSemaphore(hh, 1, NULL);
t0 = HRTime_Time();
ret = WaitForSingleObject(hh, 500);
t0 = HRTime_Time() - t0;
fprintf( stderr, "WaitForSingleObject(hh,500)==%lu took %g seconds after ReleaseSemaphore()\n",
ret, t0
);
CloseHandle(hh);
}
else{
fprintf( stderr, "Error creating semaphore: %s\n", winError(GetLastError()) );
}
ret = 0;
YieldProcessor();
fprintf( stderr, "sizeof(long)=%lu\n", sizeof(long) );
_WriteBarrier();
{ long oval, lbool;
void *ptr = NULL, *optr;
oval = _InterlockedCompareExchange( (long*) &ret, 10L, 0L );
fprintf( stderr, "_InterlockedCompareExchange(&ret==0, 10, 0) == %lu, ret==%lu\n", oval, ret );
optr = InterlockedCompareExchangePointer( &ptr, (void*) fprintf, NULL );
fprintf( stderr, "InterlockedCompareExchangePointer(&ptr==NULL, fprintf==%p, NULL) == %p, ret==%p\n",
fprintf, optr, ptr );
_InterlockedIncrement( (long*) &ret );
fprintf( stderr, "_InterlockedIncrement(&ret) ret=%lu\n", ret );
_InterlockedDecrement( (long*) &ret );
fprintf( stderr, "_InterlockedDecrement(&ret) ret=%lu\n", ret );
_ReadWriteBarrier();
lbool = false;
_InterlockedSetTrue(&lbool);
fprintf( stderr, "lbool = %ld\n", lbool );
_InterlockedSetTrue(&lbool);
fprintf( stderr, "lbool = %ld\n", lbool );
_InterlockedSetFalse(&lbool);
fprintf( stderr, "lbool = %ld\n", lbool );
}
}
#ifdef DEBUG
{ CSEScopedLock *scope = ObtainCSEScopedLock(NULL);
fprintf( stderr, "NULL testscope %p:locked==%u\n", scope, IsCSEScopeLocked(scope) );
scope = ReleaseCSEScopedLock(scope);
}
#endif
csex = CreateCSEHandle(4000);
if( !csex ){
fprintf( stderr, "Failure creating CSEHandle\n" );
exit(1);
}
else{
fprintf( stderr, "Created a '%s' CSEHandle with spinMax==%lu\n", CSEHandleInfo(csex), csex->spinMax );
}
fprintf( stderr, "GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fprintf( stderr, "GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fprintf( stderr, "GetCurrentThread() = 0x%p\n", GetCurrentThread() ); Sleep(5);
fputs( "\n", stderr );
if( (bgThread = CreateThread( NULL, 0, bgThreadSleeper, NULL, CREATE_SUSPENDED, NULL )) ){
unsigned long ret;
double tEnd;
fprintf( stderr, ">%lx t=%g will start %lx and WaitForSingleObject on it (should take 5s)\n",
GetCurrentThreadId(), HRTime_Time() - tStart, GetThreadId(bgThread) );
ResumeThread(bgThread);
// Sleep(1);
ret = WaitForSingleObject( bgThread, 1500 ); tEnd = HRTime_Time();
GetExitCodeThread( bgThread, &exitCode );
fprintf( stderr, ">%lx WaitForSingleObject(bgThread,1500)=%lu exitCode=%ld at t=%g\n",
GetCurrentThreadId(), ret, exitCode, tEnd - tStart );
ret = WaitForSingleObject( bgThread, 10000 ); tEnd = HRTime_Time();
GetExitCodeThread( bgThread, &exitCode );
fprintf( stderr, ">%lx WaitForSingleObject(bgThread,10000)=%lu exitCode=%ld at t=%g\n",
GetCurrentThreadId(), ret, exitCode, tEnd - tStart );
CloseHandle(bgThread);
}
fputs( "\n", stderr );
if( (nudgeEvent = CreateEvent( NULL, false, false, NULL )) ){
if( (bgThread = CreateThread( NULL, 0, bgThread2Nudge, NULL, 0, NULL )) ){
unsigned long ret;
double tEnd;
Sleep(1000);
fprintf( stderr, ">%lx t=%g SetEvent(nudgeEvent) = %d; sleep(1ms) and then wait for return nudge\n", GetCurrentThreadId(), HRTime_Time() - tStart, SetEvent(nudgeEvent) );
Sleep(1);
ret = WaitForSingleObject( nudgeEvent, INFINITE ); tEnd = HRTime_Time();
fprintf( stderr, ">%lx WaitForSingleObject( nudgeEvent, INFINITE ) = %lu at t=%g\n",
GetCurrentThreadId(), ret, tEnd - tStart );
ret = WaitForSingleObject( bgThread, 5000 ); tEnd = HRTime_Time();
GetExitCodeThread( bgThread, &exitCode );
fprintf( stderr, ">%lx WaitForSingleObject(bgThread,5000)=%lu exitCode=%ld at t=%g\n",
GetCurrentThreadId(), ret, exitCode, tEnd - tStart );
CloseHandle(bgThread);
}
CloseHandle(nudgeEvent);
}
fputs( "\n", stderr );
semSec.nLength = sizeof(SECURITY_ATTRIBUTES);
semSec.lpSecurityDescriptor = NULL;
semSec.bInheritHandle = true;
// semSec does not actually need to be used:
if( (nudgeEvent = CreateSemaphore( &semSec, 0, 0x7FFFFFFF, (char*) "cseSem" )) ){
if( (bgThread = CreateThread( NULL, 0, bgThread4SemTest, NULL, 0, NULL )) ){
unsigned long ret;
double tEnd;
Sleep(1000);
fprintf( stderr, ">%lx t=%g ReleaseSemaphore(nudgeEvent,1,NULL) = %d; sleep(1ms) and then wait for return nudge\n",
GetCurrentThreadId(), HRTime_Time() - tStart, ReleaseSemaphore(nudgeEvent, 1, NULL) );
Sleep(1);
ret = WaitForSingleObject( nudgeEvent, INFINITE ); tEnd = HRTime_Time();
fprintf( stderr, ">%lx WaitForSingleObject( nudgeEvent, INFINITE ) = %lu at t=%g\n",
GetCurrentThreadId(), ret, tEnd - tStart );
ret = WaitForSingleObject( bgThread, 5000 ); tEnd = HRTime_Time();
GetExitCodeThread( bgThread, &exitCode );
fprintf( stderr, ">%lx WaitForSingleObject(bgThread,5000)=%lu exitCode=%ld at t=%g\n",
GetCurrentThreadId(), ret, exitCode, tEnd - tStart );
CloseHandle(bgThread);
}
CloseHandle(nudgeEvent);
}
fputs( "\n", stderr );
if( (bgThread = CreateThread( NULL, 0, bgCSEXaccess, NULL, CREATE_SUSPENDED, NULL )) ){
fprintf( stderr, "csex is %slocked\n", (IsCSEHandleLocked(csex))? "" : "not " );
SetThreadPriority( bgThread, GetThreadPriority(GetCurrentThread()) );
fprintf( stderr, "GetThreadPriority(GetCurrentThread()) = %d\n", GetThreadPriority(GetCurrentThread()) );
ResumeThread(bgThread);
i = 0;
fprintf( stderr, "entering main csex locking loop at t=%gs\n", HRTime_toc() );
while( i < 5 ){
double t0, t1;
if( IsCSEHandleLocked(csex) ){
fprintf( stderr, "\tmain loop waiting for csex lock\n" );
}
t0 = HRTime_toc();
{
#ifdef LOCKSCOPEFG
CSEScopedLock *scope = ObtainCSEScopedLock(csex);
#else
unsigned char unlock = LockCSEHandle(csex);
#endif
t1 = HRTime_toc();
i += 1;
fprintf( stderr, "> got csex lock #%d=%d at t=%g after %gs; starting %g s wait\n",
i, IsCSEHandleLocked(csex), t1, t1-t0, SLEEPTIMEFG ); fflush(stderr);
#ifdef BUSYSLEEPING
MMSleep(SLEEPTIMEFG);
#else
do{
t1 = HRTime_toc();
} while (t1-t0 < SLEEPTIMEFG);
#endif
fprintf( stderr, "\tmain loop wait #%d ended at t=%gs; csex lock=%d\n",
i, HRTime_toc(), IsCSEHandleLocked(csex) ); fflush(stderr);
#ifndef LOCKSCOPEFG
UnlockCSEHandle( csex, unlock );
#else
scope = ReleaseCSEScopedLock(scope);
#endif
}
// just to give the other thread a chance to get a lock:
Sleep(1);
}
fprintf( stderr, "exiting main csex locking loop at t=%gs\n", HRTime_toc() );
_InterlockedSetFalse(&bgRun);
WaitForSingleObject( bgThread, 5000 );
CloseHandle(bgThread);
fprintf( stderr, "Background loop finished at t=%gs\n", HRTime_toc() );
}
else{
fprintf( stderr, "Failure creating bgCSEXaccess thread\n" );
}
DeleteCSEHandle(csex);
ASSERT(1);
ASSERT(0);
exit(0);
}
