2006-10-07 17:27:27

by Wink Saville

[permalink] [raw]
Subject: Debugging startup/frame buffer problem in 2.6.18

Hello,

I'm proceeding to debug the frame buffer problem I mentioned here, http://lkml.org/lkml/2006/10/5/22, I've added printk's and modified *_console_sem (see <Console output> & <Modifications> below) but I end up blind as debug output eventually stops. I then changed my kernel command line so it outputs to two consoles:

/boot/vmlinuz root=/dev/sda2 ro splash initcall_debug console=tty0 console=ttyS0,115200n8 loglevel=7

Still no output after trying to acquire the console sem. Anyway at this point it looks like I need to debug at a lower level. I was thinking of writing directly to the serial port or maybe there is a better choice?

Thanks,

Wink Saville


<Console output>

[ 40.267852] Calling initcall 0xffffffff8074eedc: fb_console_init+0x0/0x12c()
[ 40.275097] acquire_console_sem: drivers/video/console/fbcon.c:fb_console_init:3266
[ 40.282956] acquire_console_sem: GOT IT FOR drivers/video/console/fbcon.c:fb_console_init:3266
[ 40.282958] fb_register_client E
[ 40.282960] notifier_chain_register: E nl=ffffffff8069c9f8 n=ffffffff8069d070
[ 40.282962] notifier_chain_register: X nl=ffffffff8069c9f8 n=ffffffff8069d070
[ 40.282963] fb_register_client X
[ 40.282985] release_console_sem: drivers/video/console/fbcon.c:fb_console_init:3282
[ 40.320818] Calling initcall 0xffffffff8043ed31: nvidiafb_init+0x0/0x258()
[ 40.327889] nvidiafb_setup START
[ 40.331251] nvidiafb_probe START
[ 40.334604] ACPI: PCI Interrupt 0000:05:00.0[A] -> GSI 16 (level, low) -> IRQ 169
[ 40.342354] nvidiafb: Device ID: 10de0391
[ 40.359248] nvidiafb: CRTC0 analog found
[ 40.379285] nvidiafb: CRTC1 analog not found
[ 40.383684] nvidiafb: CRTC 0 appears to have a CRT attached
[ 40.389362] nvidiafb: Using CRT on CRTC 0
[ 40.393550] nvidia_set_fbinfo START
[ 40.397153] nvidia_set_fbinfo END
[ 40.400585] nvidiafb_check_var START
[ 40.404278] nvidiafb_check_var END
[ 40.407796] nvidia_save_vga START
[ 40.411308] nvidia_save_vga END
[ 40.414568] register_framebuffer: ENTER
[ 40.418520] register_framebuffer: num_registered_fb=1
[ 40.423710] register_framebuffer: call fb_var_to_videomode
[ 40.429306] register_framebuffer: call fb_add_videomode
[ 40.434640] register_framebuffer: call fb_notifier_call_chain
[ 40.440495] fb_notifier_call_chain E
[ 40.444187] notifier_call_chain: E nl=ffffffff8069c9f8 val=0x5 v=ffff81007ff1fcd0
[ 40.451872] notifier_call_chain: notifier_call nb=ffffffff8069d070 val=0x5 v=ffff81007ff1fcd0
[ 40.460598] fbcon_event_notify: E notifier_block=ffffffff8069d070 action=0x5 data=ffff81007ff1fcd0
[ 40.469756] fbcon_fb_registerd: -1 E idx=0
[ 40.473968] fbcon_fb_registerd: toploop i=0
[ 40.478307] fbcon_fb_registerd: info_idx = idx = 0 break
[ 40.482291] notifier_call_chain: E nl=ffffffff80671d48 val=0xc v=ffff81007ff58ef8
[ 40.482293] notifier_call_chain: notifier_call nb=ffffffff8067b590 val=0xc v=ffff81007ff58ef8
[ 40.482296] notifier_call_chain: notifier_call ret=0x0 nb=ffffffff8067b590 val=0xc v=ffff81007ff58ef8
[ 40.482298] notifier_call_chain: X ret=0x0 nl=ffffffff80671d48 val=0xc v=ffff81007ff58ef8
[ 40.482300] notifier_call_chain: E nl=ffffffff80671d48 val=0x5 v=ffff81007ff58eb8
[ 40.482302] notifier_call_chain: notifier_call nb=ffffffff8067b590 val=0x5 v=ffff81007ff58eb8
[ 40.482305] notifier_call_chain: notifier_call ret=0x0 nb=ffffffff8067b590 val=0x5 v=ffff81007ff58eb8
[ 40.482307] notifier_call_chain: X ret=0x0 nl=ffffffff80671d48 val=0x5 v=ffff81007ff58eb8
[ 40.552088] fbcon_fb_registerd: info_idx=0 call fbcon_takeover(1)
[ 40.558286] fbcon_takeover: E show_logo=1
[ 40.562407] fbcon_takeover: call take_over_console show_logo=1
[ 40.568350] take_over_console: E csw=ffffffff805d8600 first=0, last=62, deflt=1
[ 40.575859] register_con_driver: acquire_console_sem
[ 40.580933] acquire_console_sem: drivers/char/vt.c:register_con_driver:3156
[ 40.588000] acquire_console_sem: GOT IT FOR drivers/char/vt.c:register_con_driver:3156
[ 40.588001] register_con_driver: acquire_console_sem GOT IT
[ 40.588484] notifier_call_chain: E nl=ffffffff80671d38 val=0x1 v=0000000000000000
[ 40.588486] notifier_call_chain: X ret=0x0 nl=ffffffff80671d38 val=0x1 v=0000000000000000
[ 40.588491] notifier_call_chain: E nl=ffffffff80677118 val=0x0 v=ffff81007f65a810
[ 40.588493] notifier_call_chain: X ret=0x0 nl=ffffffff80677118 val=0x0 v=ffff81007f65a810
[ 40.588499] notifier_call_chain: E nl=ffffffff80671d38 val=0x2 v=0000000000000000
[ 40.588501] notifier_call_chain: X ret=0x0 nl=ffffffff80671d38 val=0x2 v=0000000000000000
[ 40.588503] notifier_call_chain: E nl=ffffffff80671d38 val=0x1 v=0000000000000000
[ 40.588506] notifier_call_chain: X ret=0x0 nl=ffffffff80671d38 val=0x1 v=0000000000000000
[ 40.588507] register_con_driver: release_console_sem
[ 40.588509] release_console_sem: drivers/char/vt.c:register_con_driver:3211
[ 40.590594] notifier_call_chain: E nl=ffffffff80671d38 val=0x2 v=0000000000000000
[ 40.590596] notifier_call_chain: X ret=0x0 nl=ffffffff80671d38 val=0x2 v=0000000000000000
[ 40.678628] notifier_call_chain: E nl=ffffffff80677128 val=0x0 v=ffff81007f65b0c0
[ 40.678631] notifier_call_chain: X ret=0x0 nl=ffffffff80677128 val=0x0 v=ffff81007f65b0c0
[ 40.710263] take_over_console: call bind_con_driver csw=ffffffff805d8600 first=0, last=62, deflt=1
[ 40.719419] bind_con_driver: E
[ 40.722586] bind_con_driver: acquire_console_sem
[ 40.727319] acquire_console_sem: drivers/char/vt.c:bind_con_driver:2742
</Console output>

<Modifications>

drivers/char/vt.c:
2727 static int bind_con_driver(const struct consw *csw, int first, int last,
2728 int deflt)
2729 {
2730 struct module *owner = csw->owner;
2731 const char *desc = NULL;
2732 struct con_driver *con_driver;
2733 int i, j = -1, k = -1, retval = -ENODEV;
2734
2735 printk("bind_con_driver: E\n");
2736 if (!try_module_get(owner)) {
2737 printk("bin_con_driver: err try_module_get\n");
2738 return -ENODEV;
2739 }
2740
2741 printk("bind_con_driver: acquire_console_sem\n");
2742 acquire_console_sem();
2743 printk("bind_con_driver: acquire_console_sem GOT IT\n");

kernel/printk.c:
752 void acquire_console_sem_real(void)
753 {
754 BUG_ON(in_interrupt());
755 if (console_suspended) {
756 down(&secondary_console_sem);
757 return;
758 }
759 down(&console_sem);
760 console_locked = 1;
761 console_may_schedule = 1;
762 }
763 EXPORT_SYMBOL(acquire_console_sem_real);
764
765 void acquire_console_sem_dbg(const char *file, const char *function, int line)
766 {
767 printk("acquire_console_sem: %s:%s:%d\n", file, function, line);
768 acquire_console_sem_real();
769 printk("acquire_console_sem: GOT IT FOR %s:%s:%d\n", file, function, line);
770 }
771 EXPORT_SYMBOL(acquire_console_sem_dbg);
772

include/linux/console.h:
125 #define acquire_console_sem() acquire_console_sem_dbg(__FILE__, __FUNCTION__, __LINE__)
126 #define try_acquire_console_sem() try_acquire_console_sem_dbg(__FILE__, __FUNCTION__, __LINE__)
127 #define release_console_sem() release_console_sem_dbg(__FILE__, __FUNCTION__, __LINE__)

</Modifications>