Powershell에서 디폴트로 멋진 Logging 기능도 함께 넣어주었으면 좋았을 텐데, 기본적으로 제공하는 로깅 기능은 없습니다.

사실 파워쉘은 Programming language와 Shell 커맨드의 두 가지 성격을 모두 가지고 있기 때문에 로깅 이외에도 여러가지 약간 섞인, 또는 양쪽 모두가 아닌 특성을 가지고 있습니다. 또, 퍼포먼스에 대해서는 다른 언어와 비교하시는 것이 의미가 없을 지도 모릅니다. 우선.

로깅전략에 대해서는 다른 언어나 어플리케이션에서도 마찬가지로 고려해야할 몇 가지 일반적인 내용이 있습니다.

기본적인 로깅을 만들어서 사용하느냐, 다기능을 지원하는 모듈을 사용하느냐?
로그 포맷은 어떻게 할 것이냐. JSON? 유연한 아웃풋을 지원하는가?
로깅이 어플리케이션에 영향을 주는가? block하는 경우가 발생하는가?
로컬에 저장할 것인가? 어딘가에 transmition할 것인가?
로그매니징은 어떻게 할 것인가? 이에대해서는 저는 parsing이 무조건 쉬워야 한다고 주장합니다.
멀티쓰레드를 지원하게 할 것인가?
- 파워쉘이니까 쉘인데 멀티쓰레드로 돌리는 것이 가능합니다.
- # 리눅스는 어떻게 하지?

파워쉘의 로깅 모듈에 대해서는 아직 정립해 가는 중입니다만, 우선 가장 많이 사용되는 logging

1
2
3
install-module logging -force 
import-module logging

Logging Module

테스트 코드

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
Install-Module Logging -Force
Import-Module Logging

Write-Log -Level 'WARNING' -Message 'Hello, {0}!' -Arguments 'Powershell'

Measure-Command  {
    $Fname = "test.log"
    Add-LoggingTarget -Name File -Configuration @{
        Path = "C:\Log\logging_$Fname"
        Append = $True
        Encoding = "utf8"
    }
    $Command = "command"
    $Action = "action"
    foreach ($i in 1..100000) {
        Write-Log -Level 'WARNING' -Message 'Hello, {0} {0}!' -Arguments $Command,$Action
    }
}

Logging Module 테스트 결과

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
Days              : 0
Hours             : 0
Minutes           : 17
Seconds           : 31
Milliseconds      : 112
Ticks             : 10511129500
TotalDays         : 0.0121656591435185
TotalHours        : 0.291975819444444
TotalMinutes      : 17.5185491666667
TotalSeconds      : 1051.11295
TotalMilliseconds : 1051112.95

이 코드는 회사의 동료가 만든 코드입니다. 초창기 버전의 Powershell코드를 사용하는 걸 보니, 예전에 사용하다가 한동안 사용하지 않았던 것 같습니다. 우선 말씀드리면 이 함수는 중요한 Logical Bug를 가지고 있습니다. 이데 대해서는 나중에 따로 설명하겠습니다.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
Function set-writelog{
    [CmdletBinding()]
    Param(
        [string] $Fname,
        [string] $Command,
        [string] $Action
    )
    try {

        $Log = @()
        $objPs = New-Object PSCustomObject
        $objPs | Add-Member -NotePropertyMembers @{DateTime = Get-Date}
        $objPs | Add-Member -NotePropertyMembers @{Function = $Fname}
        $objPs | Add-Member -NotePropertyMembers @{Command = $Command}
        $objPs | Add-Member -NotePropertyMembers @{Action = $Action}
        $Log += $objPs

        $LogFile = "C:\Log\my_" + (Get-Date).ToString("yyyyMMdd") + ".txt"

        $mutex = New-Object System.Threading.Mutex($false, "logwrite")
        $mutex.WaitOne()
        $LogText = $Log | Out-String -Stream -Width 9999 | ? {$_ -ne ""}
        $LogText += "------------------------------"
        $LogText | Out-File -FilePath $LogFile -Encoding Default -Append -Width 99999
        $mutex.ReleaseMutex()
        Return $Log
    } catch {
        Write-Error $_.Exception
    }
}

Measure-Object로 검사를 해보면 속도는 Logging 보다 낫습니다만, 위의 코드도 좀 개선의 여지는 있습니다.

1
2
3
4
5
6
7
8
Measure-Command  {
    $Fname = "test.log"
    $Command = "command"
    $Action = "action"
    foreach ($i in 1..100000) {
        set-writelog $Fname $Command $Action
    }
}

커스텀 로그 테스트 결과

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
Days              : 0
Hours             : 0
Minutes           : 14
Seconds           : 57
Milliseconds      : 611
Ticks             : 8976115423
TotalDays         : 0.0103890224803241
TotalHours        : 0.249336539527778
TotalMinutes      : 14.9601923716667
TotalSeconds      : 897.6115423
TotalMilliseconds : 897611.5423

MultiThread 환경에서 테스트하기

멀티프로세스, 멀티Thread환경에서는 어떨까요?
Powershell에서 멀티 Thread환경일 때의 동작을 확인하려면, 몇 가지 전략이 있습니다. 예를 들면

inline csharp을 이용하여 c# 으로 작성하여 실행하는 방법
New-ScheduledTask를 이용하여 여러개의 Task를 한 번에 동작시키는 방법
로컬호스트에 여려개의 세션을 열어놓고 Invoke-Command -Session $sessions 로 실행하는 방법
비동기 Task인 Job을 여러개 만들어서 실행하는 방법
RunspacePool을 이용하는 방법
pwsh 7의 Foreach-Object -Parallel 를 이용하는 방법

이 중에서 1번은 쓱쓱 적을 수 있는 난이도는 아니고, 2번과 3번은 비효율적이고, 실제 환경에서는 Powershell 5.1을 사용하기 때문에 (Get-CimInstance나 WMI, Remote Powershell을 사용해야 하므로 어쩔 수 없습니다) 환경상 적합하지 않을 수 있습니다. 여기에서는 4번, 5번, 6번을 이용해서 작성해 보려고 합니다.

단, 여기에서는 멀티태스킹으로 동작하기 때문에, 퍼포먼스에 대해서는 측정의 의미가 조금 달라지므로 생략합니다.

주의해야할 점

주의해야 할 점은, job이나 Runcspace를 정의하여 그 안에서 실행되는 scriptblock은 새로운 runspace 공간에서 실행되기 때문에, scriptblock 외부에서 정의한 함수는 내부에서는 알지 못한다는 것입니다. 그렇기 때문에 안에서 dot-sourcing이나 import-module을 사용하여 다시 로드하고 있습니다.

글로벌 변수는 접근할 수 있는 방법은 있습니다. $using:outer_variable 과 같이 접근할 수 있습니다.
# 글로번 변수중에 dictionary 타입을 사용하려면 또, ThreadSafe한 것을 사용해야 합니다.

예를 들면 다음과 같은 ConcurrentDictionary

1
$threadSafeDictionary = [System.Collections.Concurrent.ConcurrentDictionary[string,object]]::new()

4. Job을 여러개 만들어서 실행

우선 10개의 Job으로 나누어 각각 10K 번만큼 실행해보는 코드는 다음과 같습니다.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
1..10 | ForEach-Object { 
    start-job -Name $_ -ScriptBlock {
        $cmd = Get-Command "Add-LoggingTarget" -ErrorAction SilentlyContinue
        if (! $cmd) {
            Import-Module Logging

            $Fname = "test.log"
            Add-LoggingTarget -Name File -Configuration @{
                Path = "C:\Log\logging_$Fname"
                Append = $True
                Encoding = "utf8"
            }
        }

        $Command = "command"
        $Action = "action"
        foreach ($i in 1..10000) {
            Write-Log -Level 'WARNING' -Message 'Hello, {0} {0}!' -Arguments $Command,$Action
        }
    }
}

# 모두 종료할 때까지 기다렸다가
while ($Jobs.IsCompleted -contains $false) {
    Start-Sleep 1
}

# 종료한 job은 삭제합니다.
Get-job | Where-Object {$_.State -eq 'Completed'} | remove-Job

5. RunspacePool

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
$Scriptblock = {
    $cmd = Get-Command "Add-LoggingTarget" -ErrorAction SilentlyContinue
    if (! $cmd) {
        Import-Module Logging

        $Fname = "test.log"
        Add-LoggingTarget -Name File -Configuration @{
            Path = "C:\Log\logging_$Fname"
            Append = $True
            Encoding = "utf8"
        }
    }

    $Command = "command"
    $Action = "action"
    foreach ($i in 1..10000) {
        Write-Log -Level 'WARNING' -Message 'Hello, {0} {0}!' -Arguments $Command,$Action
    }
}

$MaxThreads = 10
$RunspacePool = [runspacefactory]::CreateRunspacePool(1, $MaxThreads)
$RunspacePool.Open()
$Jobs = @()

1..10 | Foreach-Object {
    $PowerShell = [powershell]::Create()
    $PowerShell.RunspacePool = $RunspacePool
    $PowerShell.AddScript($ScriptBlock).AddArgument($_)
    $Jobs += $PowerShell.BeginInvoke()
}

while ($Jobs.IsCompleted -contains $false) {
    Start-Sleep 1
}

Get-job | Where-Object {$_.State -eq 'Completed'} | remove-Job

6. Foreach-Object -Parallel

pwsh 7 이상의 환경이라면 Foreach-Object -Parallel을 사용할 수 있습니다.

기본적인 Foreach-Object 의 사용방법은 다음과 같습니다.

1
1..100 | Foreach-Object -Parallel {Start-Sleep 5}

돌려 볼까요

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
Measure-Command  {
    $Fname = "test.log"
    $Command = "command"
    $Action = "action"
    1..100000| foreach-object -Parallel {
        $f = gcm set-writelog
        if (!$f) {
            . c:\log\set-writelog.ps1
        }
        set-writelog $Fname $Command $Action
    }
}

실제로는 pwsh 7을 사용하고 있지 않기 때문에, 4번과 5번으로 테스트를 작성하고 있습니다.

정리

저는 팀의 규모상 클라우드의 프로비저닝 로직을 파워쉘에 두고 있습니다. 이런 경우, 파워쉘 함수가 멀티쓰레드로 정확히 동작하는 것은 중요합니다. 또 호스트 노드 안에서 동작하는 컴포넌트와, 컨트롤하는 컴포넌트에서 동작하는 로직은 또 다른 전략으로 접근합니다.

이번에는 로깅을 유명한 모듈을 받아 쓸까, 만들어서 쓸까 고민하다가, 멀티쓰레드 환경에서 테스트를 해봤습니다.

p025 Custom Module에서 사용하는 Logging 전략(1)