Linux ARM64: Exception Handling

[qmfrederik]

This issue track the process to get software and hardware exception handling working on ARM64 Linux.

Background: as part of #7231 we enabled building CoreCLR on Linux and got "Hello World" to run.

Lessons learned were that we need:

• llvm 3.9 to compile for arm64
• compile lldb from source (at least on Ubuntu Zesty) to debug

Current focus is on Ubuntu 17.04 (Zesty), although we may try other Linux variants in a later stage, too.

[qmfrederik]

@janvorli

This:

    class Program
    {
        static void M1()
        {
            throw new Exception("e");
        }

        static void Main(string[] args)
        {
            try
            {
                Console.WriteLine("Before M1");
                M1();
                Console.WriteLine("After M1");
            }
            catch (Exception ex)
            {
                Console.WriteLine("Caught exception {0}", ex);
            }
        }
    }

results in a hang after Before M1 is written out.

here is the backtrace:

Process 71248 launched: '/home/coreapp/corerun' (aarch64)
Before M1
Process 71248 stopped
* thread dotnet/coreclr#1, name = 'corerun', stop reason = signal SIGSTOP
    frame #0: 0x0000ffffb6f3bd74 libcoreclr.so`IsFunctionFragment(baseAddress=281471711899680, pFunctionEntry=0x0000ffff3d70bff4) at codeman.cpp:892
   889 	    }
   890 	
   891 	    // Skip epilog scopes.
-> 892 	    BOOL Ebit = (unwindHeader >> 21) & 0x1;
   893 	    if (!Ebit && (EpilogCount != 0))
   894 	    {
   895 	        // EpilogCount is the number of exception scopes defined right after the unwindHeader
(lldb) bt
* thread dotnet/coreclr#1, name = 'corerun', stop reason = signal SIGSTOP
  * frame #0: 0x0000ffffb6f3bd74 libcoreclr.so`IsFunctionFragment(baseAddress=281471711899680, pFunctionEntry=0x0000ffff3d70bff4) at codeman.cpp:892
    frame dotnet/coreclr#1: 0x0000ffffb6f3c080 libcoreclr.so`IJitManager::GetFuncletStartAddress(this=0x0000000000460e00, pCodeInfo=0x0000ffffffffcef8) at codeman.cpp:1092
    frame dotnet/coreclr#2: 0x0000ffffb6f3c100 libcoreclr.so`IJitManager::IsFunclet(this=0x0000000000460e00, pCodeInfo=0x0000ffffffffcef8) at codeman.cpp:1119
    frame dotnet/coreclr#3: 0x0000ffffb6f48d14 libcoreclr.so`EECodeInfo::IsFunclet(this=0x0000ffffffffcef8) at codeman.h:1842
    frame dotnet/coreclr#4: 0x0000ffffb6f6f73c libcoreclr.so`CrawlFrame::IsFunclet(this=0x0000ffffffffccc0) at stackwalk.h:393
    frame dotnet/coreclr#5: 0x0000ffffb724519c libcoreclr.so`ExceptionTracker::ProcessOSExceptionNotification(this=0x0000000000474e50, pExceptionRecord=0x0000000000502810, pContextRecord=0x0000000000502480, pDispatcherContext=0x0000ffffffffd4b0, dwExceptionFlags=0, sf=(SP = 281474976702800), pThread=0x0000000000476f90, STState=STS_Append) at exceptionhandling.cpp:1823
    frame dotnet/coreclr#6: 0x0000ffffb7243b78 libcoreclr.so`::ProcessCLRException(pExceptionRecord=0x0000000000502810, MemoryStackFp=281474976702800, pContextRecord=0x0000000000502480, pDispatcherContext=0x0000ffffffffd4b0) at exceptionhandling.cpp:1031
    frame dotnet/coreclr#7: 0x0000ffffb724a384 libcoreclr.so`UnwindManagedExceptionPass1(ex=0x0000ffffffffdfa0, frameContext=0x0000ffffffffd9d0) at exceptionhandling.cpp:4521
    frame dotnet/coreclr#8: 0x0000ffffb724a910 libcoreclr.so`DispatchManagedException(ex=0x0000ffffffffdfa0, isHardwareException=false) at exceptionhandling.cpp:4643
    frame dotnet/coreclr#9: 0x0000ffffb7153a58 libcoreclr.so`IL_Throw(obj=0x0000ffff18014128) at jithelpers.cpp:5451
    frame dotnet/coreclr#10: 0x0000ffff3d67940c
    frame dotnet/coreclr#11: 0x0000ffff3d670270
    frame dotnet/coreclr#12: 0x0000ffffb7254290 libcoreclr.so`CallDescrWorkerInternal at calldescrworkerarm64.S:69

[janvorli]

@qmfrederik it would be interesting to see where it keeps spinning, in other word, to which of the frames above (from 7 to 1) it never returns. I would try to set a breakpoint at the IP address that's at the frame 7. If it doesn't get hit, do the same for frame 6 etc. until you hit it.

[qmfrederik]

@janvorli

The last method for which the breakpoint is hit is UnwindManagedExceptionPass1, the breakpoint for DispatchManagedException is never hit.

  * frame #0: 0x0000ffffb724d918 libcoreclr.so`UnwindManagedExceptionPass1(ex=0x0000ffffffffdfa0, frameContext=0x0000ffffffffd9d0) at exceptionhandling.cpp:4521
    frame dotnet/coreclr#1: 0x0000ffffb724dea4 libcoreclr.so`DispatchManagedException(ex=0x0000ffffffffdfa0, isHardwareException=false) at exceptionhandling.cpp:4643

The source code for exceptionhandling.cpp is on my GitHub repo.

[janvorli]

@qmfrederik ok, thanks. Then the problem is likely in the stack unwinding getting the same address over and over. First thing to try is to enable exception handling logging by setting the following env vars before running the test app:

export COMPlus_LogEnable=1
export COMPlus_LogToConsole=1
export COMPlus_LogFacility=4000
export COMPlus_LogLevel=6

If you get me the log from the run, I can figure out the next steps.

[qmfrederik]

@janvorli Sure, here's the output:

TID 1034e: Debugger Thread spinning up
TID 1034b: InitializeExceptionHandling(): ExceptionTracker size: 0x188 bytes
TID 1034b: TrackerAllocator::Init() succeeded..
TID 1034b: SetupThread  managed Thread 0000000014110F50 Thread Id = 1
TID 1034f: SetupThread  managed Thread 000000001413D720 Thread Id = 2
Before M1
TID 1034b: ******* MANAGED EXCEPTION THROWN: Object thrown: 0000FFFF04014388 MT 0000FFFF28AEBDA8T rethrow 0
TID 1034b: Exception HRESULT = 0x80131500 Message String 0x0000FFFF04014420 (db will display) InnerException 0000000000000000 MT 0000000000000000T
TID 1034b: in Thread::SetLastThrownObject: obj = 0000FFFF04014388
TID 1034b: Processing exception at establisher=0000FFFFDC28ADA0, ip=0000FFFF28C8D40C disp->cxr: 0000FFFFDC28A620, sp: 0000FFFFDC28ADA0, cxr @ exception: 00000000141A4110
TID 1034b: ..................................................................................
TID 1034b: ProcessCLRException enter, sp = 0x0000FFFFDC28ADA0, ControlPc = 0x0000FFFF28C8D40C
TID 1034b: >>exr: 00000000141A44A0, code: e0434352, addr: 0000FFFF28C8D40C, flags: 0x00 
TID 1034b: >>NEW exception
TID 1034b: TrackerAllocator: allocating tracker 0x000000001410EE10, thread = 0x0000000014110F50
TID 1034b: ___________________________________________
TID 1034b: creating new tracker object 0x000000001410EE10, thread = 0x0000000014110F50
TID 1034b: StackTraceInfo::AllocateStackTrace (000000001410EE58)
TID 1034b: CEHelper::SetupCorruptionSeverityForActiveException - Marked non-rethrow/non-nested exception as NotCorrupting.
TID 1034b: CEHelper::SetupCorruptionSeverityForActiveException - Copied the corruption severity (2) to ThreadExceptionState.
TID 1034b: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF28C8D40C; IP in DispatcherContext->ContextRecord = 0000FFFF28C8D40C.
TID 1034b: ..ProcessCrawlFrame: PSP:  0000ffff`dc28ada0  EstablisherFrame:  0000ffff`dc28ada0 
TID 1034b: ..  A:|00| 000000001410EE10: (FFFFFFFFFFFFFFFF 0000000000000000) 1st pass
TID 1034b: ..  C:|00| 000000001410EE10: (0000FFFFDC28ADA0 0000FFFFDC28ADA0) 1st pass
TID 1034b: ..  [ ProcessExplicitFrame: pFrame:  0000ffff`dc28ac48  pMD:  00000000`00000000  FIRST PASS ]
TID 1034b: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF28C8D40C; IP in DispatcherContext->ContextRecord = 0000FFFF28C8D40C.
TID 1034b: ..  [ ProcessManagedCallFrame this=000000001410EE10, FIRST PASS ]
TID 1034b: ..  [ method: M1, ConsoleApp.Program ]
TID 1034b: ..  | uMethodStartPC: 0000FFFF28C8D3B8, ControlPc at offset 54
TID 1034b: CEHelper::CanMethodHandleException - Processing CorruptionSeverity: 2.
TID 1034b: StackTraceInfo::SaveStackTrace (000000001410EE58), alloc = 1, replace = 1, skiplast = 0
TID 1034b: StackTraceInfo::ClearStackTrace (000000001410EE58)
TID 1034b: ..returning ExceptionContinueSearch
TID 1034b: Processing exception at establisher=0000FFFFDC28ADA0, ip=0000FFFF28C8D40C disp->cxr: 0000FFFFDC28A620, sp: 0000FFFFDC28ADA0, cxr @ exception: 00000000141A4110
TID 1034b: ....................................................................................
TID 1034b: ..ProcessCLRException enter, sp = 0x0000FFFFDC28ADA0, ControlPc = 0x0000FFFF28C8D40C
TID 1034b: ..>>exr: 00000000141A44A0, code: e0434352, addr: 0000FFFF28C8D40C, flags: 0x00 
TID 1034b: ..>>continued processing of PREVIOUS exception
TID 1034b: CEHelper::SetupCorruptionSeverityForActiveException - Current tracker already has the corruption severity set.
TID 1034b: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF28C8D40C; IP in DispatcherContext->ContextRecord = 0000FFFF28C8D40C.
TID 1034b: ..ProcessCrawlFrame: PSP:  0000ffff`dc28ada0  EstablisherFrame:  0000ffff`dc28ada0 
TID 1034b: ..  A:|00| 000000001410EE10: (0000FFFFDC28ADA0 0000FFFFDC28ADA0) 1st pass
TID 1034b: ..  IGNOREFRAME: This frame has been processed already
TID 1034b: ..returning ExceptionContinueSearch
TID 1034b: Processing exception at establisher=0000FFFFDC28ADA0, ip=0000FFFF28C8D40C disp->cxr: 0000FFFFDC28A620, sp: 0000FFFFDC28ADA0, cxr @ exception: 00000000141A4110
TID 1034b: ....................................................................................
TID 1034b: ..ProcessCLRException enter, sp = 0x0000FFFFDC28ADA0, ControlPc = 0x0000FFFF28C8D40C
TID 1034b: ..>>exr: 00000000141A44A0, code: e0434352, addr: 0000FFFF28C8D40C, flags: 0x00 
TID 1034b: ..>>continued processing of PREVIOUS exception
TID 1034b: CEHelper::SetupCorruptionSeverityForActiveException - Current tracker already has the corruption severity set.
TID 1034b: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF28C8D40C; IP in DispatcherContext->ContextRecord = 0000FFFF28C8D40C.
TID 1034b: ..ProcessCrawlFrame: PSP:  0000ffff`dc28ada0  EstablisherFrame:  0000ffff`dc28ada0 
TID 1034b: ..  A:|00| 000000001410EE10: (0000FFFFDC28ADA0 0000FFFFDC28ADA0) 1st pass
TID 1034b: ..  IGNOREFRAME: This frame has been processed already
TID 1034b: ..returning ExceptionContinueSearch
TID 1034b: Processing exception at establisher=0000FFFFDC28ADA0, ip=0000FFFF28C8D40C disp->cxr: 0000FFFFDC28A620, sp: 0000FFFFDC28ADA0, cxr @ exception: 00000000141A4110
TID 1034b: ....................................................................................
TID 1034b: ..ProcessCLRException enter, sp = 0x0000FFFFDC28ADA0, ControlPc = 0x0000FFFF28C8D40C
TID 1034b: ..>>exr: 00000000141A44A0, code: e0434352, addr: 0000FFFF28C8D40C, flags: 0x00 
TID 1034b: ..>>continued processing of PREVIOUS exception
TID 1034b: CEHelper::SetupCorruptionSeverityForActiveException - Current tracker already has the corruption severity set.
TID 1034b: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF28C8D40C; IP in DispatcherContext->ContextRecord = 0000FFFF28C8D40C.
TID 1034b: ..ProcessCrawlFrame: PSP:  0000ffff`dc28ada0  EstablisherFrame:  0000ffff`dc28ada0 
TID 1034b: ..  A:|00| 000000001410EE10: (0000FFFFDC28ADA0 0000FFFFDC28ADA0) 1st pass
TID 1034b: ..  IGNOREFRAME: This frame has been processed already
TID 1034b: ..returning ExceptionContinueSearch
TID 1034b: Processing exception at establisher=0000FFFFDC28ADA0, ip=0000FFFF28C8D40C disp->cxr: 0000FFFFDC28A620, sp: 0000FFFFDC28ADA0, cxr @ exception: 00000000141A4110
TID 1034b: ....................................................................................

[janvorli]

@qmfrederik Ok, that's what I've thought. It keeps staying at the same frame. All the calls to ProcessCLRException are called with
sp = 0x0000FFFFDC28ADA0, ControlPc = 0x0000FFFF28C8D40C
That means that the RtlVirtualUnwind doesn't work for ARM64 or we give it an invalid starting point. Can you please run it again under lldb, break in after a little while and then dump the stack using the sos plugin and clrstack -f. And see if the sp and ControlPC match the first managed frame (the one that called the IL_Throw).

[qmfrederik]

@janvorli Here's what we have:

TID 1038f: ..ProcessCLRException enter, sp = 0x0000FFFFFFFFE100, ControlPc = 0x0000FFFF3D65340C
TID 1038f: ..>>exr: 00000000004EF6D0, code: e0434352, addr: 0000FFFF3D65340C, flags: 0x00 
TID 1038f: ..>>continued processing of PREVIOUS exception
TID 1038f: CEHelper::SetupCorruptionSeverityForActiveException - Current tracker already has the corruption severity set.
TID 1038f: ..ExceptionTracker::InitializeCurrentContextForCrawlFrame: DispatcherContext->ControlPC = 0000FFFF3D65340C; IP in DispatcherContext->ContextRecord = 0000FFFF3D65340C.
TID 1038f: ..ProcessCrawlFrame: PSP:  0000ffff`ffffe100  EstablisherFrame:  0000ffff`ffffe100 
TID 1038f: ..  A:|00| 000000000046CE10: (0000FFFFFFFFE100 0000FFFFFFFFE100) 1st pass
TID 1038f: ..  IGNOREFRAME: This frame has been processed already
TID 1038f: Processing exception at establisher=0000FFFFFFFFE100, ip=0000FFFF3D65340C disp->cxr: 0000FFFFFFFFD980, sp: 0000FFFFFFFFE100, cxr @ exception: 00000000004EF340

and the call stack:

OS Thread Id: 0x1038f (1)
        Child SP               IP Call Site
0000FFFFFFFFC560 0000FFFFB77684C4 libcoreclr.so!_output_s(miniFILE_struct*, char const*, std::__va_list) + 600 at /home/coreclr/src/pal/src/safecrt/output.inl:753
0000FFFFFFFFCA70 0000FFFFB7771F20 libcoreclr.so!_vsnprintf_helper(int (*)(miniFILE_struct*, char const*, std::__va_list), char*, unsigned long, char const*, std::__va_list) + 616 at /home/coreclr/src/pal/src/safecrt/vsprintf.cpp:104
0000FFFFFFFFCB20 0000FFFFB7771A5C libcoreclr.so!vsprintf_s + 540 at /home/coreclr/src/pal/src/safecrt/vsprintf.cpp:135
0000FFFFFFFFCBE0 0000FFFFB776E760 libcoreclr.so!sprintf_s + 216 at /home/coreclr/src/pal/src/safecrt/sprintf_s.cpp:79
0000FFFFFFFFCD30 0000FFFFB6F12C38 libcoreclr.so!LogSpewAlwaysValist(char const*, std::__va_list) + 144 at /home/coreclr/src/utilcode/log.cpp:324
0000FFFFFFFFCDE0 0000FFFFB6F12B80 libcoreclr.so!LogSpewValist(unsigned int, unsigned int, char const*, std::__va_list) + 140 at /home/coreclr/src/utilcode/log.cpp:270
0000FFFFFFFFCE40 0000FFFFB6F12740 libcoreclr.so!LogSpew(unsigned int, unsigned int, char const*, ...) + 224 at /home/coreclr/src/utilcode/log.cpp:401
0000FFFFFFFFCF70 0000FFFFB72469F8 libcoreclr.so!ProcessCLRException + 324 at /home/coreclr/src/vm/exceptionhandling.cpp:774
0000FFFFFFFFD300 0000FFFFB724D918 libcoreclr.so!UnwindManagedExceptionPass1(PAL_SEHException&, _CONTEXT*) + 464 at /home/coreclr/src/vm/exceptionhandling.cpp:4521
0000FFFFFFFFD890 0000FFFFB724DEA4 libcoreclr.so!DispatchManagedException(PAL_SEHException&, bool) + 440 at /home/coreclr/src/vm/exceptionhandling.cpp:4643
0000FFFFFFFFDD40 0000FFFFB71578B4 libcoreclr.so!IL_Throw(Object*) + 1340 at /home/coreclr/src/vm/jithelpers.cpp:5451
0000FFFFFFFFDFA8                  [HelperMethodFrame: 0000ffffffffdfa8] 
0000FFFFFFFFE0E0 0000FFFF3D65340C 
0000FFFFFFFFE0F0 0000FFFF3D64A270 
0000FFFFFFFFE110 0000FFFFB7257824 libcoreclr.so!CallDescrWorkerInternal + 124 at /home/coreclr/src/vm/arm64/calldescrworkerarm64.S:71

So if I understand it correctly:

	SP	Control PC
clrstack -f	0x0000FFFFFFFFE0E0	0x0000FFFF3D65340C
..ProcessCLRException	0x0000FFFFFFFFE100	0x0000FFFF3D65340C

So SP seems to be off by 0x20?

[janvorli]

@qmfrederik yes, that's the case. So it means that the libunwind based native unwinder has not unwound the SP from IL_Throw properly for some reason. Which is pretty strange given the fact that it still got the ControlPC right. The starting context is produced by the Thread::VirtualUnwindToFirstManagedCallFrame in DispatchManagedException.
Theoretically, there can also be a bug in the RtlCaptureContext that would get the initial context wrong.
What I would suggest doing now is to set a breakpoint at the Thread::VirtualUnwindToFirstManagedCallFrame, then step through the code (stepping over the calls so that you don't enter any of those). After each PAL_VirtualUnwind call, print the pContext->SP and pContext->IP and check if they match the values of the actual native frames (you can see IPs from the bt command and SP by switching to each frame and printing it).
It seems there can be two outcomes. Either the values match at all native frames and the mismatch in SP happens at the first managed frame when the loop is exited or the values don't match earlier, maybe even at the very beginning (the initial IP / SP will match the point where the RtlCaptureContext was called)

[qmfrederik]

@janvorli So I'm able to print out pContext-Sp, but pContext->IP seems to be a bit more harder:

(lldb) p pContext->IP
error: no member named 'IP' in '_CONTEXT'

(same for pContext->Ip)

[janvorli]

@qmfrederik Ah, I am sorry, it is Pc

[qmfrederik]

OK, let me see if I get this right:

Via bt and then frame select N and reg read sp, I get the following info:

Frame	IP	SP	Method
0	0x0000ffffb7041a04	0x0000ffffffffd860	Thread::VirtualUnwindToFirstManagedCallFrame
1	0x0000ffffb724de20	0x0000ffffffffd890	DispatchManagedException
2	0x0000ffffb71578b4	0x0000ffffffffdd40	IL_Throw
3	0x0000ffff3d66c40c	0x0000ffffffffe0e0
4	0x0000ffff3d663270	0x0000ffffffffe0f0

And printing out pContext->Ip and pContext->Pc after PAL_VirtualUnwind

#	Pc	Sp	OK?
0	0x0000ffffb71578b4	0x0000ffffffffdd40	OK - IL_Throw

and then we go to unwinding for the managed frames.

[janvorli]

@qmfrederik ok. And is the Sp after the next PAL_VirtualUnwind when we get to the first managed frame wrong as we have seen before? I just want to make sure that the fact that it was wrong doesn't stem from somewhere else.

[qmfrederik]

This is from a new run. So after we switch to the managed frames, the first call to PAL_VirtualUnwind is from VirtualUnwindToFirstManagedCallFrame. I can print out Pc and Sp and they seem correct. The next call to PAL_VirtualUnwind is from LazyMachState::unwindLazyState and there I've printed the values from context.

The call to PAL_VirtualUnwind in LazyMachState::unwindLazyState is the last call to PAL_VirtualUnwind I've seen (I set a breakpoint at PAL_VirtualUnwind so I'm relatively sure about that :)). The code then starts looping and outputs the same ..ProcessCLRException enter, output over and over again.

Via bt and reg read sp for the IL_Throw frame and up:

Frame	IP	SP	Method
4	0x0000ffffb71578b4	0x0000ffffffffdd40	IL_Throw
5	0x0000ffff3d67a40c	0x0000ffffffffe0e0
6	0x0000ffff3d671270	0x0000ffffffffe0f0

#	Pc	Sp	OK?	Called from
0	0x0000ffffb71578b4	0x0000ffffffffdd40	OK - IL_Throw
1	0x0000ffff3d67a40c	0x0000ffffffffe0e0	OK	VirtualUnwindToFirstManagedCallFrame
2	0x0000ffff3d67a40c	0x0000ffffffffe0e0	OK (?)	LazyMachState::unwindLazyState

[janvorli]

@qmfrederik I guess I am confused. You've said before that you were "printing out pContext->Ip and pContext->Pc after PAL_VirtualUnwind" and your table was showing that they are in the IL_Throw. So the VirtualUnwindToFirstManagedCallFrame must call the PAL_VirtualUnwind one more time to get to the managed frame. But from what you are saying now, it seems as if the PAL_VirtualUnwind was called just once from the VirtualUnwindToFirstManagedCallFrame.

[qmfrederik]

@janvorli The breakpoint at PAL_VirtualUnwind was hit three times in total - twice I believe from VirtualUnwindToFirstManagedCallFrame, hitting IL_Throw and then the first managed frame.

Then, a third time from unwindLazyState and then we enter an endless loop. The values for Pc and Sp were the same after the last two calls to PAL_VirtualUnwind unless I made a mistake when printing them. I was a bit surprised so I think I double checked.

I can verify once more tomorrow & post the results - I'm offline now.