LinuxQuestions.org
Visit Jeremy's Blog.
Home Forums Tutorials Articles Register
Go Back   LinuxQuestions.org > Forums > Linux Forums > Linux - Distributions > Fedora
User Name
Password
Fedora This forum is for the discussion of the Fedora Project.

Notices


Reply
  Search this Thread
Old 07-27-2011, 09:02 AM   #1
BGHolmes
LQ Newbie
 
Registered: Nov 2009
Location: Raleigh, NC
Distribution: FC15
Posts: 1

Rep: Reputation: 0
Boot Delay 30min: systemd-analyze blame systemd-tmpfiles-setup.service


I've got FC15 installed. Boot time was initially normal, but it now takes over 30 minutes to boot. I may have caused this problem with a lazy test program.

During boot I see the delay at point marked *DELAY* in this partial /var/log/boot.log:
...
Started /home.
Started Reconfigure the system on administrator request.
Started Mark the need to relabel after reboot.
Starting Enable all detected swap partitions...
Started Relabel all filesystems, if necessary.
Starting Recreate Volatile Files and Directories...
Starting Tell Plymouth To Write Out Runtime Data...
Starting Load Random Seed...
Started Enable all detected swap partitions.
Started Tell Plymouth To Write Out Runtime Data.
Started Load Random Seed.
*DELAY*
Started Recreate Volatile Files and Directories.
Starting Restore Sound Card State...
Starting Console System Startup Logging...
Starting Bootup unhack...
Starting Job spooling tools...
Started Job spooling tools.
...
The 'systemd-analyze blame' command shows:
[root@localhost ~]# systemd-analyze blame | head
2056232ms systemd-tmpfiles-setup.service
4236ms NetworkManager.service
3005ms avahi-daemon.service
2994ms remount-rootfs.service
2884ms media.mount
2663ms systemd-remount-api-vfs.service
2593ms fedora-sysinit-hack.service
2447ms sandbox.service
2214ms sendmail.service
2061ms hwclock-load.service
[root@localhost ~]#
This information lead me to check the /tmp directory. I initially found it full of hundreds of thousands of files (mostly empty) that were created by a lazy test program that I had been using.

Deleting those files took quite a long time, but did nothing to improve the boot time.

The size information for /tmp is a bit strange, but I am not familiar with what is normal for the directory:
[root@localhost ~]# ls -ld /tmp
drwxrwxrwt. 22 root root 611803136 Jul 27 09:17 /tmp
[root@localhost ~]# du -s /tmp
597636 /tmp
[root@localhost ~]# du /tmp
4 /tmp/.font-unix
4 /tmp/keyring-Ax7vL9
4 /tmp/.Test-unix
4 /tmp/.esd-500
4 /tmp/acroread_500_500
4 /tmp/plugtmp
8 /tmp/pulse-PKdhtXMmr18n
4 /tmp/gpg-9gVLs0
4 /tmp/orbit-zzz
4 /tmp/.ICE-unix
4 /tmp/.XIM-unix
4 /tmp/.X11-unix
4 /tmp/ssh-lRjvRm1567
4 /tmp/orbit-gdm
4 /tmp/ssh-VlFwEK1573
4 /tmp/orbit-root
4 /tmp/keyring-whxaKK
4 /tmp/pulse-yJcXyHZzsRwp
4 /tmp/hsperfdata_zzz
4 /tmp/gpg-9XH5MA
597636 /tmp
[root@localhost ~]#
My /etc/fstab is basic:
#
# /etc/fstab
# Created by anaconda on Mon Jul 25 09:32:22 2011
#
# Accessible filesystems, by reference, are maintained under '/dev/disk'
# See man pages fstab(5), findfs(8), mount(8) and/or blkid(8) for more info
#
/dev/mapper/VolGroup-lv_root / ext4 defaults 1 1
UUID=35678a95-ac6b-42bb-ad23-fb12ca43dd48 /boot ext4 defaults 1 2
/dev/mapper/VolGroup-lv_home /home ext4 defaults 1 2
/dev/mapper/VolGroup-lv_swap swap swap defaults 0 0
tmpfs /dev/shm tmpfs defaults 0 0
devpts /dev/pts devpts gid=5,mode=620 0 0
sysfs /sys sysfs defaults 0 0
proc /proc proc defaults 0 0
#
The mount command shows many tmpfs file systems:
[root@localhost ~]# mount | grep tmp
udev on /dev type devtmpfs (rw,nosuid,relatime,seclabel,size=4084672k,nr_inodes=1021168,mode=755)
tmpfs on /dev/shm type tmpfs (rw,relatime,seclabel)
tmpfs on /run type tmpfs (rw,nosuid,nodev,noexec,relatime,seclabel,mode=755)
tmpfs on /sys/fs/cgroup type tmpfs (rw,nosuid,nodev,noexec,relatime,seclabel,mode=755)
tmpfs on /media type tmpfs (rw,nosuid,nodev,noexec,relatime,rootcontext=system_ubject_r:mnt_t:s0,seclabel,mode=755)
/dev/mapper/VolGroup-lv_root on /tmp type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
/dev/mapper/VolGroup-lv_root on /var/tmp type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
[root@localhost ~]# mount
/proc on /proc type proc (rw,relatime)
/sys on /sys type sysfs (rw,relatime,seclabel)
udev on /dev type devtmpfs (rw,nosuid,relatime,seclabel,size=4084672k,nr_inodes=1021168,mode=755)
devpts on /dev/pts type devpts (rw,relatime,seclabel,gid=5,mode=620,ptmxmode=000)
tmpfs on /dev/shm type tmpfs (rw,relatime,seclabel)
tmpfs on /run type tmpfs (rw,nosuid,nodev,noexec,relatime,seclabel,mode=755)
/dev/mapper/VolGroup-lv_root on / type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
selinuxfs on /selinux type selinuxfs (rw,relatime)
tmpfs on /sys/fs/cgroup type tmpfs (rw,nosuid,nodev,noexec,relatime,seclabel,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/ns type cgroup (rw,nosuid,nodev,noexec,relatime,ns)
cgroup on /sys/fs/cgroup/cpu type cgroup (rw,nosuid,nodev,noexec,relatime,cpu)
cgroup on /sys/fs/cgroup/cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpuacct)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/net_cls type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
systemd-1 on /dev/hugepages type autofs (rw,relatime,fd=29,pgrp=1,timeout=300,minproto=5,maxproto=5,direct)
systemd-1 on /sys/kernel/security type autofs (rw,relatime,fd=30,pgrp=1,timeout=300,minproto=5,maxproto=5,direct)
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=31,pgrp=1,timeout=300,minproto=5,maxproto=5,direct)
systemd-1 on /sys/kernel/debug type autofs (rw,relatime,fd=32,pgrp=1,timeout=300,minproto=5,maxproto=5,direct)
systemd-1 on /dev/mqueue type autofs (rw,relatime,fd=34,pgrp=1,timeout=300,minproto=5,maxproto=5,direct)
tmpfs on /media type tmpfs (rw,nosuid,nodev,noexec,relatime,rootcontext=system_ubject_r:mnt_t:s0,seclabel,mode=755)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime,seclabel)
mqueue on /dev/mqueue type mqueue (rw,relatime,seclabel)
/dev/sda1 on /boot type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
/dev/mapper/VolGroup-lv_home on /home type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
/dev/mapper/VolGroup-lv_root on /tmp type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
/dev/mapper/VolGroup-lv_root on /var/tmp type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
/dev/mapper/VolGroup-lv_home on /home type ext4 (rw,relatime,seclabel,barrier=1,data=ordered)
sunrpc on /var/lib/nfs/rpc_pipefs type rpc_pipefs (rw,relatime)
[root@localhost ~]#
The /var/log/messages has one note about tmp.mount:
/var/log/messages:Jul 27 08:28:49 localhost kernel: [35660.007323] systemd[1]: tmp.mount mount process exited, code=exited status=1
/var/log/messages:Jul 27 09:03:43 localhost kernel: [ 0.399448] devtmpfs: initialized

The file shows the delay as well (the tmp.mount message above is the 19th below):
Jul 27 08:18:12 localhost dbus: [system] Successfully activated service 'net.reactivated.Fprint'
Jul 27 08:28:49 localhost avahi-daemon[888]: Got SIGTERM, quitting.
Jul 27 08:28:49 localhost avahi-daemon[888]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1
.64.
Jul 27 08:28:49 localhost modem-manager[992]: <info> Caught signal 15, shutting down...
Jul 27 08:28:49 localhost avahi-daemon[888]: avahi-daemon 0.6.30 exiting.
Jul 27 08:28:49 localhost NetworkManager[886]: <info> caught signal 15, shutting down normally.
Jul 27 08:28:49 localhost NetworkManager[886]: <warn> quit request received, terminating...
Jul 27 08:28:49 localhost NetworkManager[886]: <info> (wlan0): now unmanaged
Jul 27 08:28:49 localhost NetworkManager[886]: <info> (wlan0): device state change: activated -> unmanaged (reason 'remo
ved') [100 10 36]
Jul 27 08:28:49 localhost NetworkManager[886]: <info> (wlan0): deactivating device (reason: 36).
Jul 27 08:28:49 localhost kernel: [35659.517768] cfg80211: Calling CRDA to update world regulatory domain
Jul 27 08:28:49 localhost kernel: [35659.526653] modem-manager[992]: <info> Caught signal 15, shutting down...
Jul 27 08:28:49 localhost kernel: [35659.526662] ntpd[885]: ntpd exiting on signal 15
Jul 27 08:28:49 localhost kernel: [35659.554196] NetworkManager[886]: <info> (wlan0): canceled DHCP transaction, DHCP cl
ient pid 1831
Jul 27 08:28:49 localhost kernel: [35659.572259] smartd[890]: smartd received signal 15: Terminated
Jul 27 08:28:49 localhost kernel: [35659.648542] NetworkManager[886]: <info> (wlan0): cleaning up...
Jul 27 08:28:49 localhost kernel: [35659.648713] NetworkManager[886]: <info> (wlan0): taking down device.
Jul 27 08:28:49 localhost kernel: [35659.959670] lldpad[1196]: evb_ifdownort wlan0 remove failed
Jul 27 08:28:49 localhost kernel: [35660.007200] systemd[1]: var-lib-nfs-rpc_pipefs.mount mount process exited, code=exi
ted status=1
Jul 27 08:28:49 localhost kernel: [35660.007323] systemd[1]: tmp.mount mount process exited, code=exited status=1
Jul 27 08:28:49 localhost kernel: [35660.049705] smartd[890]: smartd is exiting (exit status 0)
Jul 27 08:28:49 localhost kernel: [35660.081583] lldpad[1196]: vdp_ifdown:wlan0 vdp data remove failed
Jul 27 08:28:49 localhost kernel: [35660.140735] cfg80211: World regulatory domain updated:
Jul 27 08:28:49 localhost kernel: [35660.140739] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, m
ax_eirp)
Jul 27 08:28:49 localhost kernel: [35660.140743] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 m
Bm)
Jul 27 08:28:49 localhost kernel: [35660.140747] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.140751] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.140754] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.140758] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.141063] cfg80211: Calling CRDA for country: US
Jul 27 08:28:49 localhost kernel: [35660.147454] cfg80211: Regulatory domain changed to country: US
Jul 27 08:28:49 localhost kernel: [35660.147455] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Jul 27 08:28:49 localhost kernel: [35660.147458] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
Jul 27 08:28:49 localhost kernel: [35660.147459] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
Jul 27 08:28:49 localhost kernel: [35660.147461] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.147463] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.147464] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.147466] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
Jul 27 08:28:49 localhost kernel: [35660.151143] pam[1445]: gdm-password[1445]: pam_unix(gdm-password:session): session closed for user Brian
Jul 27 08:28:49 localhost kernel: [35660.185997] NetworkManager[886]: <info> (p130p1): now unmanaged
Jul 27 08:28:49 localhost kernel: [35660.186010] NetworkManager[886]: <info> (p130p1): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36]
Jul 27 08:28:49 localhost kernel: [35660.186020] NetworkManager[886]: <info> (p130p1): cleaning up...
Jul 27 08:28:49 localhost kernel: [35660.186058] NetworkManager[886]: <info> (p130p1): taking down device.
Jul 27 08:28:49 localhost kernel: [35660.198431] lldpad[1196]: evb_ifdownort p130p1 remove failed
Jul 27 08:28:49 localhost kernel: [35660.198439] lldpad[1196]: vdp_ifdown130p1 vdp data remove failed
Jul 27 08:28:50 localhost kernel: Kernel logging (proc) stopped.
Jul 27 08:28:50 localhost rsyslogd: [origin software="rsyslogd" swVersion="5.8.2" x-pid="904" x-info="http://www.rsyslog.com"] exiting on signal 15.
Jul 27 09:03:43 localhost kernel: imklog 5.8.2, log source = /proc/kmsg started.
Jul 27 09:03:43 localhost rsyslogd: [origin software="rsyslogd" swVersion="5.8.2" x-pid="910" x-info="http://www.rsyslog.com"] start
Jul 27 09:03:42 localhost ntpd[888]: Listen and drop on 1 v6wildcard :: UDP 123
Jul 27 09:03:42 localhost ntpd[888]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jul 27 09:03:42 localhost ntpd[888]: Listen normally on 3 lo ::1 UDP 123
Jul 27 09:03:42 localhost ntpd[888]: peers refreshed
Jul 27 09:03:42 localhost ntpd[888]: Listening on routing socket on fd #20 for interface updates
Jul 27 09:03:43 localhost ntpd[888]: Deferring DNS for 0.fedora.pool.ntp.org 1
Jul 27 09:03:43 localhost smartd[895]: smartd 5.41 2011-06-09 r3365 [x86_64-linux-2.6.38.8-35.fc15.x86_64] (local build)
Jul 27 09:03:43 localhost smartd[895]: Copyright (C) 2002-11 by Bruce Allen, http://smartmontools.sourceforge.net
Jul 27 09:03:43 localhost smartd[895]: Opened configuration file /etc/smartd.conf
Jul 27 09:03:43 localhost smartd[895]: Configuration file /etc/smartd.conf was parsed, found DEVICESCAN, scanning devices
Jul 27 09:03:43 localhost kernel: [ 0.000000] Initializing cgroup subsys cpuset
Jul 27 09:03:43 localhost kernel: [ 0.000000] Initializing cgroup subsys cpu
Jul 27 09:03:43 localhost kernel: [ 0.000000] Linux version 2.6.38.8-35.fc15.x86_64 (mockbuild@x86-09.phx2.fedoraproject.org) (gcc version 4.6.0 20110530 (Red Hat 4.6.0-9) (GCC) ) #1 SMP Wed Jul 6 13:58:54 UTC 2011
Jul 27 09:03:43 localhost kernel: [ 0.000000] Command line: ro root=/dev/mapper/VolGroup-lv_root rd_LVM_LV=VolGroup/lv_root rd_LVM_LV=VolGroup/lv_swap rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=en_US.UTF-8 SYSFONT=latarcyrheb-sun16 KEYTABLE=us rhgb quiet
Jul 27 09:03:43 localhost kernel: [ 0.000000] BIOS-provided physical RAM map:
Jul 27 09:03:43 localhost kernel: [ 0.000000] BIOS-e820: 0000000000000000 - 000000000009dc00 (usable)
Jul 27 09:03:43 localhost kernel: [ 0.000000] BIOS-e820: 000000000009dc00 - 00000000000a0000 (reserved)
...
The /var/log/boot.log file does show one failure, but it occurs well after the delay:
...
Starting Permit User Sessions...
Started LSB: Starts the RPCSEC GSS client daemon.
Started LSB: processor frequency scaling support.
Starting LSB: start and stop kdump crash recovery service ^[[1;31mfailed^[[0m, see 'systemctl status kdump.service' for details.
Started LSB: start and stop xinetd.
Started LSB: Link Layer Discovery Protocol Agent Daemon.
Started Permit User Sessions.
...
Is there a more effective way to clean out the /tmp directory?

Is there a way to determine more about what the /var/log/messages tmp.mount message is complaining about?

Is there anything else I should look at for clues?

Thanks,

BGH
 
  


Reply



Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is Off
HTML code is Off



Similar Threads
Thread Thread Starter Forum Replies Last Post
[SOLVED] slackware and systemd fl0 Slackware 512 08-29-2012 11:07 AM
Systemd custangro Fedora 2 08-01-2011 07:54 AM
Informaton on systemd init system? arashi256 Linux - Newbie 1 06-04-2011 07:06 PM
LXer: This week at LWN: Systemd and Fedora 14 LXer Syndicated Linux News 0 09-07-2010 01:00 AM
LXer: Systemd Test Day on Tuesday 2010/09/07 LXer Syndicated Linux News 5 09-06-2010 10:52 AM

LinuxQuestions.org > Forums > Linux Forums > Linux - Distributions > Fedora

All times are GMT -5. The time now is 02:26 AM.

Main Menu
Advertisement
My LQ
Write for LQ
LinuxQuestions.org is looking for people interested in writing Editorials, Articles, Reviews, and more. If you'd like to contribute content, let us know.
Main Menu
Syndicate
RSS1  Latest Threads
RSS1  LQ News
Twitter: @linuxquestions
Open Source Consulting | Domain Registration