Failed to boot AP

[giszo]

Hi!

I'm just trying to boot the AP processors in bochs. This is how I'm doing:

I copy my SMP trampoline binary to 0x7000 with the following:

Code: Select all

memcpy( ( void* )0x7000, ( void* )&__smp_trampoline_start, trampoline_size );

When I send the SIPI to the AP I use 7 as a vector to specify the above used address:

Code: Select all

apic_write( LAPIC_ICR_LOW, 7 | /* vector */ ( 0x6 << 8 ) /* SIPI */ );

Here is the code I use as the trampoline:

Code: Select all

#include <arch/gdt.h>

.extern ap_stack_top

.section .smp_trampoline
.code16

ap_entry:
    cli

    movw %cs, %ax
    movw %ax, %ds
    movw %ax, %es

    lgdtl smp_gdtr - ap_entry
    
    /* Enable protected mode */

    movl %cr0, %eax
    orl $1, %eax
    movl %eax, %cr0
    
    /* Jump into protected mode at the kernel's 32bit SMP entry point */

    ljmpl $KERNEL_CS, $1f

smp_gdt:
    .quad 0x0000000000000000

    .word 0xFFFF /* limit */
    .word 0x0000 /* base */
    .byte 0x00   /* base */
    .byte 0x9A   /* access */
    .byte 0xCF   /* granularity */
    .byte 0x00   /* base */

    .word 0xFFFF
    .word 0x0000
    .byte 0x00
    .byte 0x92
    .byte 0xCF
    .byte 0x00
smp_gdtr:
    .word smp_gdtr - smp_gdt - 1
    .long smp_gdt
.size smp_gdtr,.-smp_gdtr

.section .text
.code32

.align 16

1:
    hlt
    jmp 1b

    movw $KERNEL_DS, %ax
    movw %ax, %ds
    movw %ax, %es
    movw %ax, %fs
    movw %ax, %ss
    /*movw %ax, %gs*/

    /* Load the stack allocated by the BSP */

    movl $ap_stack_top, %esp

    /* Enter the C part of the kernel */

    call ap_processor_entry

2:
    hlt
    jmp 2b

Here is what I get from bochs when I run my kernel:

Code: Select all

00070627495i[APIC1] CPU 1 started up at 0700:00000000 by APIC                                       
00070627500i[CPU1 ] WARNING: HLT instruction with IF=0!                                             
CPU 1: HALTED                                                                                       
CPU 0: HALTED                                                                                       
CPU 0: HALTED                                                                                       
00070637500p[CPU1 ] >>PANIC<< load_seg_reg(): invalid segment register passed!

The state of CPU1:

Code: Select all

00070637500i[CPU1 ] CPU is in protected mode (active)                                                                         
00070637500i[CPU1 ] CS.d_b = 32 bit                                                                                           
00070637500i[CPU1 ] SS.d_b = 16 bit                                                                                           
00070637500i[CPU1 ] EFER   = 0x00000000                                                                                       
00070637500i[CPU1 ] | RAX=0000000060000011  RBX=0000000000000000                                                              
00070637500i[CPU1 ] | RCX=0000000000000000  RDX=0000000000000f20                                                              
00070637500i[CPU1 ] | RSP=0000000000000000  RBP=0000000000000000                                                              
00070637500i[CPU1 ] | RSI=0000000000000000  RDI=0000000000000000                                                              
00070637500i[CPU1 ] |  R8=0000000000000000   R9=0000000000000000                                                              
00070637500i[CPU1 ] | R10=0000000000000000  R11=0000000000000000                                                              
00070637500i[CPU1 ] | R12=0000000000000000  R13=0000000000000000                                                              
00070637500i[CPU1 ] | R14=0000000000000000  R15=0000000000000000                                                              
00070637500i[CPU1 ] | IOPL=0 id vip vif ac vm rf nt of df if tf sf zf af PF cf                                                
00070637500i[CPU1 ] | SEG selector     base    limit G D                                                                      
00070637500i[CPU1 ] | SEG sltr(index|ti|rpl)     base    limit G D                                                            
00070637500i[CPU1 ] |  CS:0008( 0001| 0|  0) 00000000 000fffff 1 1                                                            
00070637500i[CPU1 ] |  DS:0700( 0000| 0|  0) 00007000 0000ffff 0 0                                                            
00070637500i[CPU1 ] |  SS:0000( 0000| 0|  0) 00000000 0000ffff 0 0                                                            
00070637500i[CPU1 ] |  ES:0700( 0000| 0|  0) 00007000 0000ffff 0 0                                                            
00070637500i[CPU1 ] |  FS:0000( 0000| 0|  0) 00000000 0000ffff 0 0                                                            
00070637500i[CPU1 ] |  GS:0000( 0000| 0|  0) 00000000 0000ffff 0 0                                                            
00070637500i[CPU1 ] |  MSR_FS_BASE:0000000000000000                                                                           
00070637500i[CPU1 ] |  MSR_GS_BASE:0000000000000000                                                                           
00070637500i[CPU1 ] | RIP=0000000000000000 (0000000000103361)                                                                 
00070637500i[CPU1 ] | CR0=0x60000011 CR1=0x0 CR2=0x0000000000000000                                                           
00070637500i[CPU1 ] | CR3=0x00000000 CR4=0x00000000                                                                           
(1).[70637500] [0x00103361] 0008:0000000000103361 (unk. ctxt): jmp .+0xfffffffd (0x00103360) ; ebfd

First I just try to halt the AP processor in protected mode but as I see the first jump after the hlt in the prot. mode entry code causes the above fault. Does anyone have an idea what could be wrong with my AP entry code?

giszo

[Brendan]

Hi,

Code: Select all

00070637500i[CPU1 ] CS.d_b = 32 bit
00070637500i[CPU1 ] SS.d_b = 16 bit

Code: Select all

00070637500i[CPU1 ] |  CS:0008( 0001| 0|  0) 00000000 000fffff 1 1
00070637500i[CPU1 ] |  DS:0700( 0000| 0|  0) 00007000 0000ffff 0 0
00070637500i[CPU1 ] |  SS:0000( 0000| 0|  0) 00000000 0000ffff 0 0
00070637500i[CPU1 ] |  ES:0700( 0000| 0|  0) 00007000 0000ffff 0 0

I'm guessing the problem might have something to do with your partial switch to protected mode - it might be better to completely switch to protected mode instead (e.g. including setting valid values for SS, DS, ES).


Cheers,

Brendan

[giszo]

Hi,

Code: Select all

00070637500i[CPU1 ] CS.d_b = 32 bit
00070637500i[CPU1 ] SS.d_b = 16 bit

Code: Select all

00070637500i[CPU1 ] |  CS:0008( 0001| 0|  0) 00000000 000fffff 1 1
00070637500i[CPU1 ] |  DS:0700( 0000| 0|  0) 00007000 0000ffff 0 0
00070637500i[CPU1 ] |  SS:0000( 0000| 0|  0) 00000000 0000ffff 0 0
00070637500i[CPU1 ] |  ES:0700( 0000| 0|  0) 00007000 0000ffff 0 0

I'm guessing the problem might have something to do with your partial switch to protected mode - it might be better to completely switch to protected mode instead (e.g. including setting valid values for SS, DS, ES).


Cheers,

Brendan

If I move the hlt loop below setting ss,ds,es I got absolutely the same results.

The code looks like the following now:

Code: Select all

1:
    movw $KERNEL_DS, %ax
    movw %ax, %ds
    movw %ax, %es
    movw %ax, %fs
    movw %ax, %ss
    /*movw %ax, %gs*/

halt:
    hlt
    jmp halt

It also doesn't matter if I set the gs or not, the same results...

Now the bochs debugger output looks like this:

Code: Select all

00052367505i[CPU1 ] CPU is in protected mode (active)                                                                         
00052367505i[CPU1 ] CS.d_b = 32 bit                                                                                           
00052367505i[CPU1 ] SS.d_b = 32 bit                                                                                           
00052367505i[CPU1 ] EFER   = 0x00000000                                                                                       
00052367505i[CPU1 ] | RAX=0000000060000010  RBX=0000000000000000                                                              
00052367505i[CPU1 ] | RCX=0000000000000000  RDX=0000000000000f20                                                              
00052367505i[CPU1 ] | RSP=0000000000000000  RBP=0000000000000000                                                              
00052367505i[CPU1 ] | RSI=0000000000000000  RDI=0000000000000000                                                              
00052367505i[CPU1 ] |  R8=0000000000000000   R9=0000000000000000                                                              
00052367505i[CPU1 ] | R10=0000000000000000  R11=0000000000000000                                                              
00052367505i[CPU1 ] | R12=0000000000000000  R13=0000000000000000                                                              
00052367505i[CPU1 ] | R14=0000000000000000  R15=0000000000000000                                                              
00052367505i[CPU1 ] | IOPL=0 id vip vif ac vm rf nt of df if tf sf zf af PF cf                                                
00052367505i[CPU1 ] | SEG selector     base    limit G D                                                                      
00052367505i[CPU1 ] | SEG sltr(index|ti|rpl)     base    limit G D                                                            
00052367505i[CPU1 ] |  CS:0008( 0001| 0|  0) 00000000 000fffff 1 1                                                            
00052367505i[CPU1 ] |  DS:0010( 0002| 0|  0) 00000000 000fffff 1 1                                                            
00052367505i[CPU1 ] |  SS:0010( 0002| 0|  0) 00000000 000fffff 1 1                                                            
00052367505i[CPU1 ] |  ES:0010( 0002| 0|  0) 00000000 000fffff 1 1                                                            
00052367505i[CPU1 ] |  FS:0010( 0002| 0|  0) 00000000 000fffff 1 1                                                            
00052367505i[CPU1 ] |  GS:0000( 0000| 0|  0) 00000000 0000ffff 0 0                                                            
00052367505i[CPU1 ] |  MSR_FS_BASE:0000000000000000                                                                           
00052367505i[CPU1 ] |  MSR_GS_BASE:0000000000000000                                                                           
00052367505i[CPU1 ] | RIP=0000000000000000 (000000000010336d)                                                                 
00052367505i[CPU1 ] | CR0=0x60000011 CR1=0x0 CR2=0x0000000000000000                                                           
00052367505i[CPU1 ] | CR3=0x00000000 CR4=0x00000000                                                                           
(1).[52367505] [0x0010336d] 0008:000000000010336d (unk. ctxt): jmp .+0xfffffffd (0x0010336c) ; ebfd

At first sight GDT looks ok to me, so I'm out of ideas what could be wrong

giszo

[Brendan]

Hi,

Let me see if I understand this... It successfully gets to the point where it locks up (HLT with interrupts disabled - a state where the CPU does nothing and the only things that can "un-lock up" the CPU are reset, SMI and INIT-IPI), but then it crashes after this, and still finds it's way to a "jmp $" instruction?

There's a large piece of this puzzle that's missing.

My next guess is that you're sending an INIT-IPI and a Startup-IPI to the AP CPU after it's already been started (because I know Bochs doesn't use SMI, and you'd know if a reset was occuring, and it's the only thing left that can break out of the "cli; hlt" loop).


Cheers,

Brendan

[giszo]

Let me see if I understand this... It successfully gets to the point where it locks up (HLT with interrupts disabled - a state where the CPU does nothing and the only things that can "un-lock up" the CPU are reset, SMI and INIT-IPI), but then it crashes after this, and still finds it's way to a "jmp $" instruction?

There's a large piece of this puzzle that's missing.

My next guess is that you're sending an INIT-IPI and a Startup-IPI to the AP CPU after it's already been started (because I know Bochs doesn't use SMI, and you'd know if a reset was occuring, and it's the only thing left that can break out of the "cli; hlt" loop).

I'm sending the INIT ipi once and then two Startup ipis as the Intel manual says. Maybe the AP starts at the first Startup ipi and the second will get the code out from the hlt instruction. But why does it causes a fault?

giszo

[Brendan]

Hi,

I'm sending the INIT ipi once and then two Startup ipis as the Intel manual says. Maybe the AP starts at the first Startup ipi and the second will get the code out from the hlt instruction.

That sounds likely to me, and I remember having similar problems myself.

Intel's method is a general purpose method, that's meant to work for a variety of different cases, including CPUs that only need one Startup-IPI (where the delay between the Startup-IPIs is meant to be very short to reduce the chance that the AP CPU has time to execute code before the second Startup-IPI arrives). However, for Bochs there is no delay at all (the AP CPU starts executing instructions immediately), and even for real CPUs it's a pain in the neck trying to get a precise time delay.

I don't use Intel's method.

Instead, I send the INIT-IPI, then have a delay (at least 10 ms, but a longer delay doesn't seem to make any difference), then send the first Startup-IPI. Then I wait for up to ~10 ms while checking to see if the AP CPU changes a synchronization variable. If the synchronization variable doesn't change after ~10 ms I send the second Startup-IPI, and if the synchronization variable still doesn't change after another ~50 ms I give up and tell the user the CPU refused to start.

For example, think of something like this:

Code: Select all

AP_CPU:
   lock inc [syncVariable]            ;Tell BSP we started
.wait1:
   pause
   cmp dword [syncVariable],0         ;Does the BSP know we started?
   je .wait1                          ; no, wait until it knows

Code: Select all

BSP_CPU:
   mov dword [syncVariable],0         ;Make sure sync variable is zero
   send_INIT_IPI();
   delay(10ms);
   send_STARTUP_IPI();
   mov ecx,[current_tick]
   xor eax,eax
   add ecx,10ms
.wait1:
   pause
   cmp [syncVariable],eax             ;Was the sync variable changed?
   jne .started                       ; yes, AP CPU was started
   cmp [current_tick],ecx             ; no, has the delay expired?
   jb .wait1                          ;     no, keep waiting

   send_STARTUP_IPI();
   mov ecx,[current_tick]
   xor eax,eax
   add ecx,50ms
.wait2:
   pause
   cmp [syncVariable],eax             ;Was the sync variable changed?
   jne .started                       ; yes, AP CPU was started
   cmp [current_tick],ecx             ; no, has the delay expired?
   jb .wait2                          ;     no, keep waiting
   jmp .giveUp                        ;     yes, give up on this CPU

.started:
   lock dec dword [syncVariable]      ;Make sure sync variable is zero again (to let AP CPU continue)

But why does it causes a fault?

Is the second Startup-IPI identical, has the trampoline code been overwritten by the AP CPU's stack (or anything else), was there any variables or locks that may have been used and left in an unexpected state?

Note: You should be able to figure out exactly what's going on by single-stepping with Bochs. For e.g. put a breakpoint just before the code that sends the Startup-IPI and single-step. Also, for Bochs debugger there's an undocumented "set $cpu = 1" that may be very useful (so you can debug CPU#1 instead of debugging CPU#0)...


Cheers,

Brendan

[giszo]

Now I temporaly removed the second Startup IPI and this version looks better. I don't get the fault now

I don't use Intel's method.

Instead, I send the INIT-IPI, then have a delay (at least 10 ms, but a longer delay doesn't seem to make any difference), then send the first Startup-IPI. Then I wait for up to ~10 ms while checking to see if the AP CPU changes a synchronization variable. If the synchronization variable doesn't change after ~10 ms I send the second Startup-IPI, and if the synchronization variable still doesn't change after another ~50 ms I give up and tell the user the CPU refused to start.

I will rewrite my code according to this idea, thanks!

Note: You should be able to figure out exactly what's going on by single-stepping with Bochs. For e.g. put a breakpoint just before the code that sends the Startup-IPI and single-step. Also, for Bochs debugger there's an undocumented "set $cpu = 1" that may be very useful (so you can debug CPU#1 instead of debugging CPU#0)...

Wow! I'm looking for that "set $cpu = 1" command for days! Thanks for that as well

Now I'm going to solve my final problem... Why the APIC timer doesn't work on AP processors under Bochs

giszo

[giszo]

After fixing the AP segment error and some APIC hacking now I can boot 8 processors in bochs and with the local APIC timer interrupt I can increment a character on the screen to show its really working. But a new problem just come up

If I put a kprintf() call to the AP initialization function then I hit some kind of locking problem around the initialization of CPU #4. Without this kprintf() everything is okey, all the 8 CPUs are working correctly.

I have a spinlock that makes my kprintf() function secure in a multithreaded point of view. This is how my kprintf looks like:

Code: Select all

void kprintf( const char* format, ... ) {
    va_list va;

    spinlock_disable( &screen_lock );
    
    va_start( va, format );
    do_printf( kprintf_helper, NULL, format, va );
    va_end( va );

    spinunlock_enable( &screen_lock );
}

spinlock_disable() first disables the interrupts on the current CPU and then tries to lock a sponlock. spinunlock_enable() first releases the previously locked spinlock and then reenables the interrupts according to the enable_interrupts boolean if it was enabled before getting to the locked section. The return_after_lock variable in the spinlock definition is only for debugging purposes. Here's the corresponding code:

Code: Select all

typedef struct spinlock {
    atomic_t locked;
    bool enable_interrupts;
    uint32_t return_after_lock;
} spinlock_t;

static inline void spinlock( spinlock_t* lock ) {
    while ( atomic_swap( &lock->locked, 1 ) == 1 ) {
        __asm__ __volatile__( "pause" );
    }
    lock->return_after_lock = ( uint32_t )__builtin_return_address( 0 );
}

static inline void spinlock_disable( spinlock_t* lock ) {
    bool ints = disable_interrupts();
    spinlock( lock );
    lock->enable_interrupts = ints;
}

static inline void spinunlock( spinlock_t* lock ) {
    lock->return_after_lock = 0;
    atomic_set( &lock->locked, 0 );
}

static inline void spinunlock_enable( spinlock_t* lock ) {
    bool ints = lock->enable_interrupts;
    spinunlock( lock );
    if ( ints ) {
        enable_interrupts();
    }
}

There are two functions, atomic_set() and atomic_swap() that I use in the spinlock code. They are implemented as assembler parts of the kernel:

Code: Select all

atomic_get:
    movl 4(%esp), %edx
    movl (%edx), %eax
    ret
.size atomic_get,.-atomci_get

atomic_swap:
    movl 4(%esp), %edx
    movl 8(%esp), %eax
    lock
    xchgl %eax, (%edx)
    ret
.size atomic_swap,.-atomic_swap

During SMP initialization first I start the AP and then I wait until it is started with a timeout. If the AP started normally I print "CPU n started.", otherwise I print an error message. In the AP initialization I use kprintf() to print for example "Setting up APIC timer".

And the interesting part comes now! CPU #0 and CPU #4 has some kind of problem because they don't spin the character associated with them on the screen. CPU #2 and CPU #3 works fine with spinning a character on the screen. After the lockup happened I hit Ctrl+C to enter the bochs debugger, and what I see from the EIP and disassembled code is that CPU #0 and CPU #4 tries to acquire the kprintf spinlock. By printing the memory region that contains the screen_lock spinlock structure I got the value of return_after_lock. It points to the ap initialization function to the instruction after the kprintf() call.

How the hell is this possible? Do I have something wrong in my spinlock code?

Ps.:

Here's the BSP code that initializes the APs and the AP boot code if you're interested in it:

Code: Select all

int arch_boot_processors( void ) {
    int i;
    size_t trampoline_size;

    trampoline_size = ( size_t )&__smp_trampoline_end - ( size_t )&__smp_trampoline_start;

    memcpy( ( void* )0x7000, ( void* )&__smp_trampoline_start, trampoline_size );

    for ( i = 1; i < processor_count; i++ ) {
        int j;

        kprintf( "Booting CPU %d ...\n", i );

        ap_stack_top = ( uint32_t )alloc_pages( 2 );
        ap_stack_top += PAGE_SIZE * 2;
        ap_stack_top -= sizeof( register_t );
        ap_running = 0;

        /* Send INIT to the AP */

        apic_write( LAPIC_ICR_HIGH, processor_table[ i ].apic_id << 24 );
        apic_write(
            LAPIC_ICR_LOW,
            ( 0x5 << 8 ) /* INIT */
        );

        /* Wait until it is delivered */

        while ( apic_read( LAPIC_ICR_LOW ) & ( 1 << 12 ) ) ;

        /* Give 10ms to the AP to initialize itself */

        thread_sleep( 10000 );

        int times_to_wait_for_ap[] = {
            10000, /* 10ms */
            50000, /* 50ms */
        };

        for ( j = 0; j < ( sizeof( times_to_wait_for_ap ) / sizeof( int ) ) && !ap_running; j++ ) {
            /* Send SIPI to the AP */

            apic_write( LAPIC_ICR_HIGH, processor_table[ i ].apic_id << 24 );
            apic_write(
                LAPIC_ICR_LOW,
                7 | /* vector */
                ( 0x6 << 8 ) /* SIPI */
            );

            /* Wait until it is delivered */

            while ( apic_read( LAPIC_ICR_LOW ) & ( 1 << 12 ) ) ;

            thread_sleep( times_to_wait_for_ap[ j ] );
        }

        if ( ap_running ) {
            int tries = 0;

            do {
                thread_sleep( 10000 );
            } while ( ( !processor_table[ i ].running ) && ( tries++ < 500 ) );

            if ( processor_table[ i ].running ) {
                kprintf( "CPU %d is running!\n", i );
            } else {
                kprintf( "CPU %d started but failed to finish booting!\n", i );
            }
        } else {
            kprintf( "Failed to start up CPU %d\n", i );
        }
    }

    return 0;
}

Code: Select all

void ap_processor_entry( void ) {
    gdt_t gdtp;
    idt_t idtp;
    i386_memory_context_t* arch_context = kernel_memory_context.arch_data;

    /* Enable paging */

    __asm__ __volatile__(
        "movl %0, %%cr3\n"
        "movl %%cr0, %0\n"
        "orl $0x80000000, %0\n"
        "movl %0, %%cr0\n"
        :
        : "r" ( arch_context->page_directory )
    );

    /* Load GDT */

    gdtp.size = sizeof( gdt ) - 1;
    gdtp.base = ( uint32_t )&gdt;

    __asm__ __volatile__(
        "lgdt %0\n"
        :
        : "m" ( gdtp )
    );

    reload_segment_descriptors();

    /* Load IDT */

    idtp.limit = ( sizeof( idt_descriptor_t ) * IDT_ENTRIES ) - 1;
    idtp.base = ( uint32_t )&idt;

    __asm__ __volatile__(
        "lidt %0\n"
        :
        : "m" ( idtp )
    );

    /* Configure local APIC */

    get_processor()->running = 1;

    kprintf( "Setting up APIC timer\n" );

    setup_local_apic();
    setup_apic_timer();

    //kprintf( "CPU %d: Enabling interrupts\n", get_processor_id() );

    asm("sti");

    while ( 1 ) { asm("hlt"); }
}

giszo

[LoseThos]

Where did you get an 8 CPU machine? I assume you are talking about an Core i7, nehalem? I want to buy one

[giszo]

Where did you get an 8 CPU machine? I assume you are talking about an Core i7, nehalem? I want to buy one

Lol... As I mentioned before I'm using Bochs to test my kernel

[giszo]

I figured out what was the problem. It was caused by loading wrong ESP value during the AP boot process.

Now I'm able to run my scheduler on 8 cores...

giszo

[tantrikwizard]

I figured out what was the problem. It was caused by loading wrong ESP value during the AP boot process.

Now I'm able to run my scheduler on 8 cores...

giszo

Gratz!