Thx for your local try :)
However, I still have this issue. So I have manage to provide more info
First of all, I got below on a VirtualBox (but this happens in my real
hardware, which is a dell desktop)
[root@08-00-27-a9-9a-26 ~]# uname -v
joyent_20140501T225642Z
[root@08-00-27-a9-9a-26 ~]# time rmformat -l
Looking for devices...
1. Logical Node: /dev/rdsk/c0t1d0p0
Physical Node: /pci@0,0/pci8086,2829@d/cdrom@1,0
Connected Device: VBOX CD-ROM 1.0
Device Type: DVD Reader
Bus: <Unknown>
Size: 679.7 MB
Label: <None>
Access permissions: <Unknown>
real 1m0.143s
user 0m0.006s
sys 0m0.024s
You can see that 1m real time. Actually, the results before the Label line
populates out first, then after 1m, Label and access lines appear.
I have done some dtrace stuff (but I am not a dtrace expert :)), the script
is
[root@08-00-27-a9-9a-26 /opt]# cat r.d
syscall:::entry
/pid == $target/
{
self->t = timestamp;
}
syscall:::return
/self->t/
{
@systime[execname, probefunc] = sum(timestamp - self->t);
self->t = 0;
}
dtrace:::END
{
printa("%15s %15s %@15u\n", @systime);
}
And the results are:
[root@08-00-27-a9-9a-26 /opt]# dtrace -s r.d -c "rmformat -l"
dtrace: script 'r.d' matched 465 probes
Looking for devices...
1. Logical Node: /dev/rdsk/c0t1d0p0
Physical Node: /pci@0,0/pci8086,2829@d/cdrom@1,0
Connected Device: VBOX CD-ROM 1.0
Device Type: DVD Reader
Bus: <Unknown>
Size: 679.7 MB
Label: <None>
Access permissions: <Unknown>
dtrace: pid 62472 has exited
CPU ID FUNCTION:NAME
0 2 :END rmformat
labelsys 1953
rmformat setcontext 2342
rmformat sigpending 2610
rmformat privsys 2736
rmformat getrlimit 3048
rmformat zone 3458
rmformat getuid 3852
rmformat gtime 3905
rmformat uname 4287
rmformat getpid 4856
rmformat readlink 4922
rmformat sysconfig 6722
rmformat sysi86 7311
rmformat lstat64 7379
rmformat llseek 10993
rmformat fcntl 13843
rmformat chdir 19534
rmformat fstat64 24672
rmformat schedctl 25876
rmformat getcwd 27494
rmformat brk 30545
rmformat openat 42381
rmformat memcntl 48134
rmformat mmap 52093
rmformat resolvepath 65762
rmformat getdents64 67369
rmformat lwp_cond_broadcast 91472
rmformat munmap 92840
rmformat fstat 114936
rmformat read 134970
rmformat open64 157031
rmformat putmsg 191423
rmformat write 193405
rmformat stat64 226050
rmformat mmapobj 326062
rmformat close 384007
rmformat open 513954
rmformat lwp_sigmask 551511
rmformat getmsg 12365946
rmformat ioctl 53940501
rmformat pollsys 60016272302
So the obvious thing is that pollsys use too much time. And I believe that
it is just retry and sleep for sth. So this may be more complex than I
think (or even it is not in the rmformat side, it should only do simple
things.)
To reproduce the situation, I believe you can just use
smartos_20140501T225642Z.iso to boot the system in a VirtualBox VM.
I will also try to use your smartos version for a try, may be this issue is
gone while nobody notice it (except me :)).
On Sat, May 31, 2014 at 2:23 AM, Keith Wesolowski <
[email protected]> wrote:
> On Fri, May 30, 2014 at 04:29:52PM +0800, Yu Li wrote:
>
> > Sorry for such a delay. Anyway I have managed to populate the truss log
> >
> > the interesting part is as follows
> >
> > getpid() = 10843 [10842]
> > fstat(7, 0x08046868) = 0
> > ioctl(7, I_STR, 0x080469B0) = 0
> > time() = 1401438253
> > fstat(7, 0x080468E8) = 0
> > putmsg(7, 0x08046A04, 0x08046AD4, 0) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) (sleeping...)
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) = 0
> > fstat(7, 0x080468E8) = 0
> > putmsg(7, 0x08046A04, 0x08046AD4, 0) = 0
> >
> > pollsys(0x080A4A24, 1, 0x08046A38, 0x00000000) (sleeping...)
> >
> > (...and this continues to previous one)
> >
> > I suspect that this is just sth wrong in reading my usb's bus info, and
> > have to retry to many times?
>
> What is being polled here? You can either use DTrace to look at this in
> more detail or use the debugger to see what's in the poll structure.
> Then use pfiles so see what that refers to.
>
> This is probably going to be a lot easier with DTrace; I'd start with
> something simple like looking at the kernel stacks at the time we go off
> CPU, which will tell us what the poll is actually waiting on (which is
> what we want to know anyway).
>
> Since it would be easier to debug this myself, I tried it here locally,
> but could not reproduce the behaviour you are seeing:
>
> [root@headnode (sf-3) ~]# uname -v
> joyent_20140519T165600Z
> [root@headnode (sf-3) ~]# time rmformat -l
> Looking for devices...
> 1. Logical Node: /dev/rdsk/c16t0d0p0
> Physical Node: /pci@0,0/pci15d9,702@1d/hub@1/storage@7/disk@0,0
> Connected Device: Kingston DT Rubber 3.0 1.01
> Device Type: Removable
> Bus: USB
> Size: 15.0 GB
> Label: <Unknown>
> Access permissions: <Unknown>
>
> real 0m0.029s
> user 0m0.004s
> sys 0m0.013s
>
> That means this is most likely going to be something specific to your
> hardware, or perhaps to the data on your USB key or some other device.
> Maybe OS-1952 or something like it is involved
> (http://smartos.org/bugview/OS-1952).
>
-------------------------------------------
smartos-discuss
Archives: https://www.listbox.com/member/archive/184463/=now
RSS Feed: https://www.listbox.com/member/archive/rss/184463/25769125-55cfbc00
Modify Your Subscription:
https://www.listbox.com/member/?member_id=25769125&id_secret=25769125-7688e9fb
Powered by Listbox: http://www.listbox.com
