Bug 112613 - ls(1): 'ls -l' is very slow or doesn't work at all
Summary: ls(1): 'ls -l' is very slow or doesn't work at all
Status: Open
Alias: None
Product: Base System
Classification: Unclassified
Component: bin (show other bugs)
Version: 6.2-STABLE
Hardware: Any Any
: Normal Affects Only Me
Assignee: Mark Linimon
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-05-12 14:10 UTC by Vyacheslav Silakov
Modified: 2020-07-11 02:35 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Vyacheslav Silakov 2007-05-12 14:10:04 UTC
Copyright (c) 1992-2007 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
        The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 6.2-STABLE #3: Fri May 11 15:45:11 MSD 2007
    seal@gw.inar.ru:/usr/obj/usr/src/sys/GW
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: Intel Pentium III (866.43-MHz 686-class CPU)
  Origin = "GenuineIntel"  Id = 0x68a  Stepping = 10
  Features=0x387fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,PN,MMX,FXSR,SSE>
real memory  = 3221159936 (3071 MB)
avail memory = 3154182144 (3008 MB)
ACPI APIC Table: <INTEL  024B    >
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
 cpu0 (BSP): APIC ID:  3
 cpu1 (AP): APIC ID:  0
ioapic0 <Version 1.1> irqs 0-15 on motherboard
ioapic1 <Version 1.1> irqs 16-31 on motherboard
kbd1 at kbdmux0
acpi0: <INTEL 024B> on motherboard
acpi0: Overriding SCI Interrupt from IRQ 9 to IRQ 31
acpi0: Power Button (fixed)
Timecounter "ACPI-safe" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x404-0x407 on acpi0
acpi_ec0: <Embedded Controller: GPE 0x4> port 0xca6,0xca7 on acpi0
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
acpi_button0: <Sleep Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pci0: <display, VGA> at device 2.0 (no driver attached)
fxp0: <Intel 82559 Pro/100 Ethernet> port 0x5400-0x543f mem 0xf8101000-0xf8101fff,0xf8000000-0xf80fffff irq 18 at device 3.0 on pci0
miibus0: <MII bus> on fxp0
inphy0: <i82555 10/100 media interface> on miibus0
inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp0: Ethernet address: 00:d0:b7:b7:d8:48
pcib1: <PCI-PCI bridge> at device 7.0 on pci0
pci1: <PCI bus> on pcib1
asr0: <Adaptec Caching SCSI RAID> mem 0xfa000000-0xfbffffff irq 23 at device 7.1 on pci0
asr0: [GIANT-LOCKED]
asr0: ADAPTEC 2100S FW Rev. 3607, 1 channel, 256 CCBs, Protocol I2O
isab0: <PCI-ISA bridge> port 0x580-0x58f at device 15.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <ServerWorks ROSB4 UDMA33 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x374-0x377,0x5440-0x544f at device 15.1 on pci0
ata0: <ATA channel 0> on atapci0
ata2: <ATA channel 1> on atapci0
pcib2: <ACPI Host-PCI bridge> on acpi0
pci2: <ACPI PCI bus> on pcib2
acpi_tz0: <Thermal Zone> on acpi0
acpi_tz1: <Thermal Zone> on acpi0
acpi_tz2: <Thermal Zone> on acpi0
sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
sio0: type 16550A
sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0
sio1: type 16550A
ppc0: <ECP parallel printer port> port 0x378-0x37f,0x778-0x77f irq 7 drq 3 on acpi0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/8 bytes threshold
ppbus0: <Parallel port bus> on ppc0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fdc0: [FAST]
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
pmtimer0 on isa0
orm0: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xc97ff,0xc9800-0xcf7ff on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
Timecounters tick every 1.000 msec
IP Filter: v4.1.13 initialized.  Default = pass all, Logging = enabled
ipfw2 initialized, divert enabled, rule-based forwarding enabled, default to accept, logging limited to 100 packets/entry by default
acd0: CDROM <CDU5211/YYS2> at ata0-master PIO4
ses0 at asr0 bus 0 target 6 lun 0
ses0: <ESG-SHV SCA HSBP M14 0.03> Fixed Processor SCSI-2 device
ses0: SAF-TE Compliant Device
da0 at asr0 bus 0 target 0 lun 0
da0: <ADAPTEC RAID-5 3607> Fixed Direct Access SCSI-2 device
da0: Tagged Queueing Enabled
da0: 105009MB (215058432 512 byte sectors: 255H 63S/T 13386C)
SMP: AP CPU #1 Launched!
Trying to mount root from ufs:/dev/da0s1a

# df -hi
Filesystem     Size    Used   Avail Capacity iused   ifree %iused  Mounted on
/dev/da0s1a    496M     74M    382M    16%    1623   64167    2%   /
devfs          1.0K    1.0K      0B   100%       0       0  100%   /dev
/dev/da0s1d    2.9G    1.9G    780M    71%  226039  174343   56%   /usr
/dev/da0s1e     46G     28G     15G    65%   39429 6201849    1%   /var1
/dev/da0s1f     46G     27G     15G    65%  769148 5472130   12%   /var2
devfs          1.0K    1.0K      0B   100%       0       0  100%   /var1/var/named/dev

cd /usr/bin
ls -l
works fine.

'ls -l' in any big dir (with more than 100 files) in /var1 or /var2
doesn't work or works very slowly. btw, 'ls' without options works fine.
Problem is appeared on this hardware after upgrade 4.11-STABLE to 6.2-STABLE.

Fix: 

none
Comment 1 Remko Lodder freebsd_committer 2007-05-12 16:28:36 UTC
State Changed
From-To: open->closed

Yes we have problems with the submission interface but submitting this 
much tickets eventhough there are mentionings that you should wait a 
little you didnt do it. Close this ticket as duplicate of 112612
Comment 2 Mats Palmgren 2007-05-13 14:48:48 UTC
This doesn't look like a duplicate of bug 112612.
Comment 3 Remko Lodder freebsd_committer 2007-05-13 16:57:49 UTC
State Changed
From-To: closed->open

I got over excited and closed too much, reopen this one.
Comment 4 Mark Linimon freebsd_committer freebsd_triage 2007-05-14 07:58:27 UTC
State Changed
From-To: open->feedback

Can you tell us more about what you have on those filesystems? 

Sample results I get on 6.2: 

$ ls | wc -l 
1006 
$ ls -al 
[deleted] 
0.07 real         0.00 user         0.01 sys
Comment 5 Vyacheslav Silakov 2007-05-14 12:23:44 UTC
Some details:

# mount
/dev/da0s1a on / (ufs, local)
devfs on /dev (devfs, local)
/dev/da0s1d on /usr (ufs, local, soft-updates)
/dev/da0s1e on /var1 (ufs, local, with quotas, soft-updates)
/dev/da0s1f on /var2 (ufs, local, with quotas, soft-updates)
devfs on /var1/var/named/dev (devfs, local)

Contents of /var1 and /var2 is restored from tar-ball created on the
previous version of OS 4.11-STABLE (news spool, mail spool, users home dirs,
etc).

Btw, 'deco' program doesn't have any problems with full file listing.
Comment 6 Vyacheslav Silakov 2007-07-01 20:57:45 UTC
Ok... ;)

I've a look into ls.c.
It seems to be a performance problem around string #702
[...]
user = user_from_uid(sp->st_uid, 0);
[...]

My /etc/passwd contains about 10,000 records and /var/mail directory
contains about 10,000 mailboxes. Probably 'user_from_uid' function is doing
something wrong.

Original timing:
# time ls -l /var/mail
[...]
    1572.20 real       133.71 user       790.94 sys

But when I'm changed 
user = user_from_uid(sp->st_uid, 0);
to
user = "blablabla";
result is:

# time ./ls -l /var/mail
[...]
       17.01 real         0.20 user         0.22 sys

p.s. 'deco' program works fine because it doesn't use 'user_from_uid'
function calls.
Comment 7 Volker 2008-03-08 15:37:40 UTC
Vyacheslav,

can you please try if you're getting a massive timing difference if
using `ls -fn'?

-f no sort
-n no UID/GID translation

If so, I would be interested in getting timing results of -f and -n
alone. I expect you seeing a delay when not using -n (thinking you're
having a huge user base and thus a large /etc/passwd?).

Thanks!
Comment 8 Volker Werth freebsd_committer 2008-03-08 15:38:29 UTC
Responsible Changed
From-To: freebsd-bugs->vwe


grab
Comment 9 Vyacheslav Silakov 2008-03-09 21:55:28 UTC
Hello!

> -----Original Message-----
> From: Volker [mailto:volker@vwsoft.com]
> Sent: Saturday, March 08, 2008 6:38 PM
> To: bug-followup@FreeBSD.org; seal@inar.ru
> Subject: Re: bin/112613: ls(1): 'ls -l' is very slow or doesn't work at
> all
> 
> Vyacheslav,
> 
> can you please try if you're getting a massive timing difference if
> using `ls -fn'?
> 
> -f no sort
> -n no UID/GID translation
> 
> If so, I would be interested in getting timing results of -f and -n
> alone. I expect you seeing a delay when not using -n (thinking you're
> having a huge user base and thus a large /etc/passwd?).

/var/mail# time ls -l
[...]
     1367.35 real       168.53 user       858.78 sys

/var/mail# time ls -ln
[...]
     5.58 real         0.26 user         0.44 sys

/var/mail# time ls -lf
[...]
     1260.51 real       166.10 user       852.66 sys

/var/mail# ls -ln | wc -l
   10470

/var/mail# wc -l /etc/passwd
   10044 /etc/passwd

/var/mail# uname -a
FreeBSD xxxxx.yyy.ru 6.3-STABLE FreeBSD 6.3-STABLE #16: Fri Feb 29 02:11:00
MSK 2008     seal@xxxxx.yyy.ru:/usr/obj/usr/src/sys/XXXXX  i386

Again, 'deco' program (see ports) havn't such delay problem.

> 
> Thanks!
Comment 10 Rebecca Cran freebsd_committer 2008-03-09 22:27:13 UTC
I've profiled a run of "ls -l" in /var/mail with 10,000 users each with 
their own file in /var/mail.   The problem appears to be in 
compat_passwd: it's called 10002 times; it in turn called hash_access, 
pwdb_match_entry_v4, hash_get and compat_is_excluded 50225023 times.

hash_access uses most of the time within compat_passwd: it calls 
__get_buf which in turn calls __get_page which calls __sys_read.
The __sys_read function took 70% of the CPU time.

--
Bruce
Comment 11 Volker Werth freebsd_committer 2008-03-09 22:33:51 UTC
State Changed
From-To: feedback->open


reset feedback, we're already looking if this is possible to fix and 
have done measurements.
Comment 12 Volker Werth freebsd_committer 2008-04-28 22:17:06 UTC
State Changed
From-To: open->analyzed


Bruce did some testing, we've checked the code and the issue is clear now -> set to analyzed. 
Unfortunately we don't have a nice solution handy (in terms of code)
Comment 13 Alexander Best freebsd_committer 2011-01-05 02:20:06 UTC
any updates on this issue? i've tested this on /home on
{hub,freefall}.freebsd.org and can still verify the issue.

cheers.
alex

-- 
a13x
Comment 14 Eitan Adler freebsd_committer freebsd_triage 2018-05-28 19:47:41 UTC
batch change:

For bugs that match the following
-  Status Is In progress 
AND
- Untouched since 2018-01-01.
AND
- Affects Base System OR Documentation

DO:

Reset to open status.


Note:
I did a quick pass but if you are getting this email it might be worthwhile to double check to see if this bug ought to be closed.
Comment 15 Mark Linimon freebsd_committer freebsd_triage 2020-07-11 02:35:57 UTC
To submitters: is this still a problem in recent versions of FreeBSD?