adapters/srw_lock.c

// Copyright (C) Microsoft Corporation. All rights reserved.

#include <inttypes.h>
#include <stdbool.h>

#include "windows.h"

#include "azure_c_shared_utility/xlogging.h"
#include "azure_c_shared_utility/gballoc.h"
#include "azure_c_shared_utility/timer.h"
#include "azure_c_shared_utility/string_utils.h"

#include "azure_c_shared_utility/srw_lock.h"

/*
vocabulary:
blaBlaCount = values of counter for event blabla
blablaCounts = sum of individual blablaCountEnd-blablaCountBegin (always a sum of durations of Counts)
time = blablaCounts/freq
*/

#define TIME_BETWEEN_STATISTICS_LOG 600 /*in seconds, so every 10 minutes*/

typedef struct SRW_LOCK_HANDLE_DATA_TAG
{
    
    SRWLOCK lock;

    LARGE_INTEGER freq;

    volatile LONG64 nCalls_AcquireSRWLockExclusive; /*number of calls to AcquireSRWLockExclusive*/
    volatile LONG64 totalCounts_AcquireSRWLockExclusive; /*how many counts were spent taking the lock (that is, just before and after AcquireSRWLockExclusive call*/
    volatile LONG64 totalCounts_ReleaseSRWLockExclusive; /*how many counts were spent releasing the exclusive SRW that is, just before and after ReleaseSRWLockExclusive call*/
    volatile LONG64 lastCount_AcquireSRWLockExclusive; /*last time the lock was taken exclusively*/
    volatile LONG64 totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive; /*how much time the lock was taken in total in exclusive mode*/

    volatile LONG64 nCalls_AcquireSRWLockShared; /*number of calls to AcquireSRWLockShared*/
    volatile LONG64 totalCounts_AcquireSRWLockShared; /*how many counts were spent taking the lock (that is, just before and after AcquireSRWLockShared */
    volatile LONG64 totalCounts_ReleaseSRWLockShared; /*how many counts were spent releasing the shared SRW that is, just before and after ReleaseSRWLockShared call*/
    volatile LONG nSharedReaders; /*if lock_shared is granted, then there are 1 more readers... when readers gets to 0, the shared "locked" count can be updated*/
    volatile LONG64 firstCount_AcquireSRWLockShared; /*first time the lock was taken in shared mode*/
    volatile LONG64 totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared; /*how much time the lock was taken from the first granted shared access to the last released shared access*/

    LARGE_INTEGER handleCreateCount; /*when the handle was created*/

    TIMER_HANDLE timer;

    char* lockName;
    bool doStatistics;
    
}SRW_LOCK_HANDLE_DATA;


static void LogStatistics(SRW_LOCK_HANDLE handle, const char* reason)
{
    LARGE_INTEGER now;
    (void)QueryPerformanceCounter(&now);

    /*print statistics*/

LogInfo("srw_lock_statistics reason:%s SRW_LOCK_HANDLE handle %p lock_name=%s\n"
"freq=%" PRId64 ",\n"
"nCalls_AcquireSRWLockExclusive=%" PRId64 ",\n"
"totalCounts_AcquireSRWLockExclusive=%" PRId64 ",\n"
"totalCounts_ReleaseSRWLockExclusive=%" PRId64 ",\n"
"totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive=%" PRId64 ",\n"
"nCalls_AcquireSRWLockShared=%" PRId64 ",\n"
"totalCounts_AcquireSRWLockShared=%" PRId64 ",\n"
"totalCounts_ReleaseSRWLockShared=%" PRId64 ",\n"
"totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared=%" PRId64 ",\n"
"totalCountsBetween_Create_and_Now=%" PRId64 ",\n"
"totalTimeBetween_Create_and_Now[s]=%.2f, \n"
"totalTimeBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive[s]=%.2f, \n"
"totalTimeBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive[%%]=%.2f, \n"
"averageTimeBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive[us]=%.2f, \n"
"totalTimeBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared[s]=%.2f, \n"
"totalTimeBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared[%%]=%.2f",

reason,
handle,
handle->lockName,
handle->freq.QuadPart,
InterlockedAdd64(&handle->nCalls_AcquireSRWLockExclusive, 0),
InterlockedAdd64(&handle->totalCounts_AcquireSRWLockExclusive, 0),
InterlockedAdd64(&handle->totalCounts_ReleaseSRWLockExclusive, 0),
InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, 0),
InterlockedAdd64(&handle->nCalls_AcquireSRWLockShared, 0),
InterlockedAdd64(&handle->totalCounts_AcquireSRWLockShared, 0),
InterlockedAdd64(&handle->totalCounts_ReleaseSRWLockShared, 0),
InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared, 0),
/*"totalTimeBetween_Create_and_Now[s]*/
now.QuadPart - handle->handleCreateCount.QuadPart,
(double)(now.QuadPart -handle->handleCreateCount.QuadPart)/ (double)handle->freq.QuadPart,
(double)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, 0) / (double)handle->freq.QuadPart,
(double)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, 0) / (double)(now.QuadPart - handle->handleCreateCount.QuadPart) *100,
(InterlockedAdd64(&handle->nCalls_AcquireSRWLockExclusive, 0)>0?(double)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, 0)*1000000 / (double)(now.QuadPart - handle->handleCreateCount.QuadPart) / InterlockedAdd64(&handle->nCalls_AcquireSRWLockExclusive, 0):-1),
(double)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared , 0) / (double)handle->freq.QuadPart,
(double)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared, 0) / (double)(now.QuadPart - handle->handleCreateCount.QuadPart) * 100
);

}

SRW_LOCK_HANDLE srw_lock_create(bool do_statistics, const char* lock_name)
{
    SRW_LOCK_HANDLE result;
    /*Codes_SRS_SRW_LOCK_02_001: [ srw_lock_create shall allocate memory for SRW_LOCK_HANDLE. ]*/
    result = calloc(1, sizeof(SRW_LOCK_HANDLE_DATA));
    if (result == NULL)
    {
        /*return as is*/
        LogError("failure in malloc(sizeof(SRW_LOCK_HANDLE_DATA)=%zu)", sizeof(SRW_LOCK_HANDLE_DATA));
    }
    else
    {
        /*Codes_SRS_SRW_LOCK_02_023: [ If do_statistics is true then srw_lock_create shall copy lock_name. ]*/
        if (do_statistics &&
            ((result->lockName= sprintf_char("%s", MU_P_OR_NULL(lock_name))) == NULL)
        )
        {
            LogError("failure in sprintf_char(\"%%s\", lock_name=%s)", MU_P_OR_NULL(lock_name));
        }
        else
        {
            /*Codes_SRS_SRW_LOCK_02_024: [ If do_statistics is true then srw_lock_create shall create a new TIMER_HANDLE by calling timer_create. ]*/
            if(
                do_statistics &&
                ((result->timer = timer_create())==NULL)
                )
            {
                LogError("failure in timer_create()");
            }
            else
            {
                result->doStatistics = do_statistics;
                /*Codes_SRS_SRW_LOCK_02_015: [ srw_lock_create shall call InitializeSRWLock. ]*/

                InitializeSRWLock(&result->lock);

                (void)QueryPerformanceFrequency(&result->freq);

                (void)InterlockedExchange64(&result->nCalls_AcquireSRWLockExclusive, 0);
                (void)InterlockedExchange64(&result->nCalls_AcquireSRWLockShared, 0);

                (void)InterlockedExchange64(&result->totalCounts_AcquireSRWLockExclusive, 0);
                (void)InterlockedExchange64(&result->totalCounts_ReleaseSRWLockExclusive, 0);

                (void)InterlockedExchange64(&result->totalCounts_AcquireSRWLockShared, 0);
                (void)InterlockedExchange64(&result->totalCounts_ReleaseSRWLockShared, 0);

                (void)InterlockedExchange64(&result->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, 0);

                (void)InterlockedExchange(&result->nSharedReaders, 0);
                (void)InterlockedExchange64(&result->totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared, 0);


                (void)QueryPerformanceCounter(&result->handleCreateCount);

                if (do_statistics)
                {
                    LogInfo("srw_lock_create returns %p for lock_name=%s", result, MU_P_OR_NULL(lock_name));
                }
                /*Codes_SRS_SRW_LOCK_02_003: [ srw_lock_create shall succeed and return a non-NULL value. ]*/
                goto allOk;

                //timer_destroy(result->timer);
            }
            /*Codes_SRS_SRW_LOCK_02_004: [ If there are any failures then srw_lock_create shall fail and return NULL. ]*/
            do_statistics ? free(result->lockName) : (void)0;
        }
        free(result);
        result = NULL;
    }
allOk:;
    return result;
    
}

void srw_lock_acquire_exclusive(SRW_LOCK_HANDLE handle)
{
    /*Codes_SRS_SRW_LOCK_02_022: [ If handle is NULL then srw_lock_acquire_exclusive shall return. ]*/
    if (handle == NULL)
    {
        LogError("invalid argument SRW_LOCK_HANDLE handle=%p", handle);
    }
    else
    {
        if (!handle->doStatistics)
        {
            AcquireSRWLockExclusive(&handle->lock);
        }
        else
        {
            LARGE_INTEGER start, stop;
            (void)QueryPerformanceCounter(&start);
            /*Codes_SRS_SRW_LOCK_02_006: [ srw_lock_acquire_exclusive shall call AcquireSRWLockExclusive. ]*/
            AcquireSRWLockExclusive(&handle->lock);
            (void)QueryPerformanceCounter(&stop); /*measure acquire time*/

            (void)InterlockedIncrement64(&handle->nCalls_AcquireSRWLockExclusive);
            (void)InterlockedAdd64(&handle->totalCounts_AcquireSRWLockExclusive, stop.QuadPart - start.QuadPart);

            /*piggyback on the lock itself to print the statistics "until now" - note - does not include the current Lock call*/
            /*Codes_SRS_SRW_LOCK_02_025: [ If do_statistics is true and if the timer created has recorded more than TIME_BETWEEN_STATISTICS_LOG seconds then statistics will be logged and the timer shall be started again. ]*/
            if (timer_get_elapsed(handle->timer) >= TIME_BETWEEN_STATISTICS_LOG)
            {
                timer_start(handle->timer);
                LogStatistics(handle, "periodic logging almost every " MU_TOSTRING(TIME_BETWEEN_STATISTICS_LOG) " seconds");
            }

            (void)InterlockedExchange64(&handle->lastCount_AcquireSRWLockExclusive, stop.QuadPart);
        }
    }
}

void srw_lock_release_exclusive(SRW_LOCK_HANDLE handle)
{
    /*Codes_SRS_SRW_LOCK_02_009: [ If handle is NULL then srw_lock_release_exclusive shall return. ]*/
    if (handle == NULL)
    {
        LogError("invalid argument SRW_LOCK_HANDLE handle=%p", handle);
    }
    else
    {
        if (!handle->doStatistics)
        {
#ifdef _MSC_VER
#pragma warning(disable:26110) // Warning C26110: Caller failing to hold lock 'handle->lock' before calling function 'ReleaseSRWLockExclusive'.
#endif
            ReleaseSRWLockExclusive(&handle->lock);
#ifdef _MSC_VER
#pragma warning (default:26110)
#endif
        }
        else
        {
            LARGE_INTEGER start, stop;

            LARGE_INTEGER lastAcquireCount_exclusive_copy;
            lastAcquireCount_exclusive_copy.QuadPart = InterlockedAdd64(&handle->lastCount_AcquireSRWLockExclusive, 0);

            (void)QueryPerformanceCounter(&start);
            /*Codes_SRS_SRW_LOCK_02_010: [ srw_lock_release_exclusive shall call ReleaseSRWLockExclusive. ]*/
#ifdef _MSC_VER
#pragma warning(disable:26110) // Warning C26110: Caller failing to hold lock 'handle->lock' before calling function 'ReleaseSRWLockExclusive'.
#endif
            ReleaseSRWLockExclusive(&handle->lock);
#ifdef _MSC_VER
#pragma warning (default:26110)
#endif
            (void)QueryPerformanceCounter(&stop); /*measure release time*/

            (void)InterlockedAdd64(&handle->totalCounts_ReleaseSRWLockExclusive, (stop.QuadPart - start.QuadPart));
            (void)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockExclusive_and_ReleaseSRWLockExclusive, (stop.QuadPart - lastAcquireCount_exclusive_copy.QuadPart));
        }
    }
}

void srw_lock_acquire_shared(SRW_LOCK_HANDLE handle)
{
    /*Codes_SRS_SRW_LOCK_02_017: [ If handle is NULL then srw_lock_acquire_shared shall return. ]*/
    if (handle == NULL)
    {
        LogError("invalid argument SRW_LOCK_HANDLE handle=%p", handle);
    }
    else
    {
        if (!handle->doStatistics)
        {
            AcquireSRWLockShared(&handle->lock);
        }
        else
        {
            LARGE_INTEGER start, stop;

            (void)QueryPerformanceCounter(&start);
            /*Codes_SRS_SRW_LOCK_02_018: [ srw_lock_acquire_shared shall call AcquireSRWLockShared. ]*/
            AcquireSRWLockShared(&handle->lock);
            (void)QueryPerformanceCounter(&stop); /*measure acquire time*/

            /*there is one more shared reader*/
            /*is this the first reader?*/
            if (InterlockedIncrement(&handle->nSharedReaders) == 1)
            {
                (void)InterlockedExchange64(&handle->firstCount_AcquireSRWLockShared, stop.QuadPart);
            }

            (void)InterlockedIncrement64(&handle->nCalls_AcquireSRWLockShared);
            (void)InterlockedAdd64(&handle->totalCounts_AcquireSRWLockShared, stop.QuadPart - start.QuadPart);

            /*Codes_SRS_SRW_LOCK_02_026: [ If do_statistics is true and the timer created has recorded more than TIME_BETWEEN_STATISTICS_LOG seconds then statistics will be logged and the timer shall be started again. ]*/
            if (timer_get_elapsed(handle->timer) >= TIME_BETWEEN_STATISTICS_LOG)
            {
                timer_start(handle->timer);
                LogStatistics(handle, "periodic logging almost every " MU_TOSTRING(TIME_BETWEEN_STATISTICS_LOG) " seconds");
            }
        }
    }
}

void srw_lock_release_shared(SRW_LOCK_HANDLE handle)
{
    /*Codes_SRS_SRW_LOCK_02_020: [ If handle is NULL then srw_lock_release_shared shall return. ]*/
    if (handle == NULL)
    {
        LogError("invalid argument SRW_LOCK_HANDLE handle=%p", handle);
    }
    else
    {
        if (!handle->doStatistics)
        {
            ReleaseSRWLockShared(&handle->lock);
        }
        else
        {
            LARGE_INTEGER start, stop;

            LARGE_INTEGER firstCount_AcquireSRWLockShared_copy;
            firstCount_AcquireSRWLockShared_copy.QuadPart = InterlockedAdd64(&handle->firstCount_AcquireSRWLockShared, 0);

            (void)QueryPerformanceCounter(&start);
            /*Codes_SRS_SRW_LOCK_02_021: [ srw_lock_release_shared shall call ReleaseSRWLockShared. ]*/
            ReleaseSRWLockShared(&handle->lock);
            (void)QueryPerformanceCounter(&stop); /*measure release time*/

            if (InterlockedDecrement(&handle->nSharedReaders) == 0)
            {
                (void)InterlockedAdd64(&handle->totalCountsBetween_AcquireSRWLockShared_and_ReleaseSRWLockShared, (stop.QuadPart - firstCount_AcquireSRWLockShared_copy.QuadPart));
            }

            (void)InterlockedAdd64(&handle->totalCounts_ReleaseSRWLockShared, (stop.QuadPart - start.QuadPart));
        }
    }
}

void srw_lock_destroy(SRW_LOCK_HANDLE handle)
{
    /*Codes_SRS_SRW_LOCK_02_011: [ If handle is NULL then srw_lock_destroy shall return. ]*/
    if (handle == NULL)
    {
        LogError("invalid arguments SRW_LOCK_HANDLE handle=%p", handle);
    }
    else
    {
        if (handle->doStatistics)
        {
            LogStatistics(handle, "srw_lock_destroy was called");
            timer_destroy(handle->timer);
            free(handle->lockName);
        }

        /*Codes_SRS_SRW_LOCK_02_012: [ srw_lock_destroy shall free all used resources. ]*/
        /*there's no deinit for a SRW, since it is a static construct*/
        free(handle);
    }
}