Project

General

Profile

Bug #660

Ten second delay during login due to 'modunload -i 0'

Added by Nick Zivkovic about 9 years ago. Updated over 8 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Desktop (JDS)
Target version:
Start date:
2011-01-23
Due date:
2011-09-14
% Done:

100%

Estimated time:
40.00 h
Difficulty:
Medium
Tags:
needs-triage

Description

Every time I log in via GDM, there is a ten second delay (on both of my x86 machines, running OI_148). I did some anonymous tracing and found that it took ten seconds for modunload -i 0 to complete. On gnome desktops this doesn't seem unusual, as full desktops take a while to load. But since I run dwm, this delay was a smoking gun.

Below is partial output from the resulting trace. The leftmost column is the timestamp in nanoseconds from the beginning of the boot sequence. The right most column is the
execname and pid. Near the bottom you'll see that modunload takes more than 10 seconds, while anonymous tracing is enabled. When disabled, it takes exactly 10. I've attached the D script for this output, and the full output as well.

I was able to find out that the arguments to modunload were '-i' and '0', by having dtrace stop the process as soon as it began execution, and then telling dtrace to invoke gcore to get the core. Which I later inspected with mdb. I attached this script as well.

My old opensolaris 134 never experienced a delay during login, so I assume that this is a regression and therefor a bug.

If there are any flaws in my analysis please let me know.

Also, the scripts are counter-intuitively named, for reasons I can't recall.

Thanks,
-Nick

....
28194741306 EXEC [svcprop, 697]
28268150679 EXEC [svcprop, 699]
28272835345 EXEC [svcprop, 701]
28278013231 EXEC [svcprop, 702]
28285104968 EXEC [ksh93, 703]
28290289019 EXEC [rc3, 703]
28301360533 EXEC [uname, 705]
28337551637 EXEC [ksh93, 708]
28342105101 EXEC [svc-zones, 708]
31172641597 EXEC [pkginfo, 734]
31205125169 EXEC [gconf-sanity-che, 741]
31741390817 EXEC [gdm-simple-greet, 752]
31749064454 EXEC [gnome-power-mana, 753]
32063233497 EXEC [hal-is-caller-pr, 757]
33311492326 EXEC [modunload, 707]
33314818728 EXEC [modunload, 707]
50015846420 EXEC [ksh93, 760]
50019402918 EXEC [pargs, 760]
50020545735 EXEC [pargs, 760]
50055970288 EXEC [ck-get-x11-serve, 762]
50173569786 EXEC [audioctl, 769]
50186411390 EXEC [ksh93, 772]
50192000915 EXEC [cpp, 772]
50216592549 EXEC [echo, 775]
50236841573 EXEC [xmodmap, 777]
50242513208 EXEC [postrun-query, 780]
50247566469 EXEC [ksh, 780]
50264204753 EXEC [pkginfo, 783]
50294669941 EXEC [linc-cleanup-soc, 791]
50304540433 EXEC [dbus-launch, 792]
50310677351 EXEC [dbus-daemon, 794]
50323962498 EXEC [xset, 797]
50347573657 EXEC [ssh-agent, 763]
50353157092 EXEC [dwm, 763]
52303319606 EXEC [utmp_update, 801]
52312099753 EXEC [zsh, 800]
52343975904 EXEC [cat, 803]
62648113920 EXEC [pfexec, 809]
62650262210 EXEC [dtrace, 809]
62652470361 EXEC [dtrace, 809]


Files

mod-pre-boot.d (288 Bytes) mod-pre-boot.d This is the D script that temporarily stops modunload and grabs its core. Nick Zivkovic, 2011-01-23 10:48 PM
mod-boot.d (162 Bytes) mod-boot.d This is the D script that timestamps each exec-success from the start of the boot sequence. Nick Zivkovic, 2011-01-23 10:48 PM
anon_boot_ts (26 KB) anon_boot_ts This is the full output of mod-boot.d Nick Zivkovic, 2011-01-23 10:48 PM

History

#1

Updated by Ken Mays over 8 years ago

  • Due date set to 2011-09-14
  • Category set to Desktop (JDS)
  • Status changed from New to Feedback
  • Assignee set to OI JDS
  • Target version set to oi_151_stable
  • Estimated time set to 40.00 h
  • Difficulty set to Medium
  • Tags set to needs-triage
#2

Updated by Ken Mays over 8 years ago

  • Status changed from Feedback to Resolved
  • % Done changed from 0 to 100

Resolved in oi_151a test.

Also available in: Atom PDF