Using Mutexes to Write Data to the Same Logfile Across Processes With PowerShell

I think we have all been there at some point. We have multiple processes running, either through multiple powershell.exe consoles or using PSJobs (maybe even runspaces Smile) and we have decided that specific data from our running commands should go to a single logfile. Well what do you think will happen at some point when 2 (or more) commands collide?

image

Yes, the dreaded “cannot access file…because it is in use by another process” that we have come to know and despise. This little error and cause unnecessary data loss on your file and a lot of frustration when you see it happening.

The answer to this question is using a Mutex (http://msdn.microsoft.com/en-us/library/windows/desktop/ms686927(v=vs.85).aspx | http://msdn.microsoft.com/en-us/library/system.threading.mutex(v=vs.110).aspx). In my case, I am going to show you a named mutex. With a named mutex, we can specify a mutex with a name on one process and then tell it to take the mutex and on another process (yes, another PowerShell console would work) and call the same named mutex and if we attempt to take the mutex, it will create a blocking call until the other process relinquishes control of it. What this allows us to do is have multiple processes that can write to a single file without fear of missing data due to the file being locked.

Note: If working in a Terminal Server, prefix name with “Global\” to make mutex available in all sessions and “Local\” if you wish to make the mutex available in the current working session.

To create a named mutex, we can do the following:

 
$mtx = New-Object System.Threading.Mutex($false, "TestMutex")

image

This is actually creating the mutex and specifying a name (TestMutex) while specifying $False as I do not want to own this mutex yet. Next up is actually taking control of the mutex so nothing else can attempt to hold it.

 
$mtx.WaitOne()

image

If nothing else has ownership of the mutex, then it will automatically move on to the next command, otherwise it will perform a blocking call, meaning that you cannot do anything else until the other process gives up the mutex. Note that you can specify a timeout (in milliseconds) that will cause your attempt to return $False (instead of $True) if the timeout has been reached.

 
$mtx.WaitOne(1000)

SNAGHTML222a03cc

As you can see, while one process has the mutex, the other process eventually times out while waiting to get the mutex. Now if we do not specify a timeout, we will see the console block…

SNAGHTML22372147

…Until I release the mutex on the other process. Then I can write the logfile.

 
$mtx.WaitOne()
'other important data' | Out-File C:\importantlogfile.txt -Append
$mtx.ReleaseMutex()

SNAGHTML22396711

To get a better idea about this, I wrote a little script to run on separate processes. Here is the script code:

 
$Log = "C:\temp\log.txt"
1..10 | ForEach {
    Write-Verbose "Attempting to grab mutex" -Verbose
    $mtx = New-Object System.Threading.Mutex($false, "TestMutex")
    If ($mtx.WaitOne(1000)) { #Calling WaitOne() without parameters creates a blocking call until mutex available
        Write-Verbose "Recieved mutex!" -Verbose
        $Sleep = Get-Random (1..5)
        #Simulate writing data to log file
        Write-Verbose "Writing data $($_) to $log" -Verbose
        Start-Sleep -Seconds $Sleep
        Write-Verbose "Releasing mutex" -Verbose
        [void]$mtx.ReleaseMutex()
    } Else {
        Write-Warning "Timed out acquiring mutex!"
    }
}
$mtx.Dispose()
Write-Verbose 'Finished!' –Verbose

Now I will run it on two PowerShell processes and observe what happens.

image

Here you can see that both processes will take turn (for the most part) in grabbing the mutex and writing to a logfile. Sometimes though, it will timeout and attempt to grab the mutex again.

That was pretty cool, but let’s overcomplicate this by adding runspaces into the mix and by showing examples of both using mutexs and not using mutexs just to further illustrate why you should use a mutex when writing to a single logfile. Note that the source code will be available at the end of this article due to its length. The name of the script is called Invoke-MutexTestRunspace.ps1.

No Mutexs

 
.\Invoke-MutexTestRunspace.ps1 –NoMutex –Logfile C:\Testlog.txt

image

Here we see on the right that there were some missed writes to the logfile due to the process on the left currently holding a lock on it. Now to use the mutexs and see what happens.

Using a Mutex

 
.\Invoke-MutexTestRunspace.ps1 –Logfile C:\Testlog.txt

image

This shows that both processes are sharing time writing to the common logfile by waiting as each one holds onto the mutex and then once it has been released, is taken by the next process and proceeds to write to the logfile.

So with that, you can see how to use a mutex to allow for multiple processes writing to the same logfile (or actually anything else that you can think of) without fear of losing data from a process due to a file lock.

Source Code for Invoke-MutexTestRunspace.ps1

 
Param (
    $LogFile = 'C:\testlog.txt',
    $Throttle = 20,
    $Count = 100,
    [switch]$NoMutex
)

$Parameters = @{
    LogFile = $LogFile
    NoMutex = $NoMutex
}

$DebugPreference = 'Continue'

$RunspacePool = [runspacefactory]::CreateRunspacePool(
    1, #Min Runspaces
    10, #Max Runspaces
    [System.Management.Automation.Runspaces.InitialSessionState]::CreateDefault(), #Initial Session State; defines available commands and Language availability
    $host #PowerShell host
)

$RunspacePool.Open()

$jobs = New-Object System.Collections.ArrayList

1..$Count | ForEach {
    $PowerShell = [powershell]::Create()
    
    $PowerShell.RunspacePool = $RunspacePool
    
    [void]$PowerShell.AddScript({
        Param(
            $LogFile,
            $NoMutex
        )
        If (-Not $NoMutex) {
            $mtx = New-Object System.Threading.Mutex($false, "LogMutex")
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Requesting mutex!" -Verbose
            $mtx.WaitOne()
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Recieved mutex!" -Verbose        
        }
        Try {
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Writing data $($_) to $LogFile" -Verbose
            "[$(Get-Date)] | ThreadID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId) | ProcessID $($PID) | Data: $($_)" | Out-File $LogFile -Append
        } Catch {
            Write-Warning $_
        }
        If (-Not $NoMutex) {
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Releasing mutex" -Verbose
            [void]$mtx.ReleaseMutex()
        }
    })

    [void]$PowerShell.AddParameters($Parameters)

    $Handle = $PowerShell.BeginInvoke()
    $temp = '' | Select PowerShell,Handle
    $temp.PowerShell = $PowerShell
    $temp.handle = $Handle
    [void]$jobs.Add($Temp)
    
    Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
    Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
        $_.handle.iscompleted -ne 'Completed'
    }).Count)
}

#Verify completed
Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
    $_.handle.iscompleted -ne 'Completed'
}).Count)

$return = $jobs | ForEach {
    $_.powershell.EndInvoke($_.handle);$_.PowerShell.Dispose()
}
$jobs.clear()

About Boe Prox

Microsoft Cloud and Datacenter MVP working as a SQL DBA.
This entry was posted in powershell and tagged , , , . Bookmark the permalink.

4 Responses to Using Mutexes to Write Data to the Same Logfile Across Processes With PowerShell

  1. Nick says:

    Can you show me an example or provide a template for incorporating this Mutex script within a PoshRS script? I have a PoshRS multithreaded script that works fine but would like to use mutexes to assure that each process that is writing to a CSV waits for it to become available.

  2. Normally inside of C# th System.Threading.Monitor Class is used to sync Threads.
    This class should run a bit faster then a Systemwide Mutex.
    (For now I do not know how to use Monitor with runspaces 😉 )

    Because Mutexes are a Systemwide Object and can be accessd by all Processes on a System, a Mutex are normally used to sync Processes so this is perfect for PowerShell Jobs 😉
    Here is my (imperfect) Function i use to sync PowerShell Jobs.

    Function Test-Mutex {

    [CmdletBinding()]
    param(
    [String]$MutexName,
    [Switch]$CreateMutex
    )

    Add-Type -AssemblyName ‘System.Threading’

    Try
    {
    $Mutex = [System.Threading.Mutex]::OpenExisting($MutexName)
    Write-Verbose “Mutex already exist! MutexName: $MutexName”
    }
    Catch [System.Threading.WaitHandleCannotBeOpenedException]
    {
    If($CreateMutex)
    {
    Write-Verbose “Mutex does not Exist! Creating Mutex with Name: $MutexName”
    $Mutex = New-Object System.Threading.Mutex($true,$MutexName)
    }
    Else
    {
    # Mutex does not exist from another Tread or Process
    # so there is seemingly no need to Synchronize, so we return $True
    Write-Verbose ‘Mutex does not Exist and we do not create one! Returning True!’
    Return $True
    }
    }

    # Mutex was existing or created so we test if we can obtain the acces to the Mutex 
    

    Write-Verbose “Test if we can obtain the acces to the Mutex with Name: $MutexName”
    $Mutex.WaitOne(0,$True)
    }

    Greets Peter Kriegel
    founder member of the German speaking PowerShell Community
    http://www.PowerShell-Group.eu

    • Boe Prox says:

      Yep, mutexes will work great inside of a PSJob as each PSJob that is created is under a new process. I didn’t really demo that in this article because it was easier to show it under a runspace (although I did show that in 2 separate PowerShell consoles using a named mutex).

      I covered System.Threading.Monitor in a presentation back in June (sample code and slide deck available here: ) and mentioned their use in runspaces. Mainly you would use the Monitor to ‘lock’ and ‘unlock’ a synchronized collection (hash table, array, etc..) to avoid race conditions when attempting to write to the same collection from multiple threads.

      Thank you for your comment.

  3. Steve says:

    Absolutely brilliant! I was recently looking for a solution to this file-lock problem while using runspaces and this solution fits in perfectly. Not really worried much about the little extra overhead of time it takes to complete but have a peace of mind that nothing is lost yet use concurrent executions to the fullest. Thank you so much.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s