newfs locks entire machine for 20seconds

classic Classic list List threaded Threaded
17 messages Options
Reply | Threaded
Open this post in threaded view
|

newfs locks entire machine for 20seconds

Steven Hartland
I'm just in the midst of setting up a new machine using 7.0-PRERELEASE
and while running newfs to init the data partitions the entire machine
stalled for a good 20seconds when processing a 500GB partition.

I had a number of windows open at the time including:-
1. gstat
2. top showing IO inc system @ 1 second intervals
3. newfs window

The newfs had completed its output, gstat was showing 95% usage on da0
and da0s3g and top was showing no IO users ( all 0% ).

At this point everything froze for ~ 20 seconds then returned to normal.

The machine is running with ULE on 7.0 as mention using an Areca 1220
controller over 8 disks in RAID 6 + Hotspare.

17:44:38 => 17:45:05

Rerunning the newfs reproduces the issue which is good so where do I
go from here?

I'm really interested in looking into this as we have production
machines which are also suffering from intermittent stalls which
could well be related.

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Ivan Voras
Steven Hartland wrote:

> The machine is running with ULE on 7.0 as mention using an Areca 1220
> controller over 8 disks in RAID 6 + Hotspare.

I'd suggest you first try to reproduce the stall without ULE, while
keeping all other parameters exactly the same.

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland
----- Original Message -----
From: "Ivan Voras" <[hidden email]>


> Steven Hartland wrote:
>
>> The machine is running with ULE on 7.0 as mention using an Areca 1220
>> controller over 8 disks in RAID 6 + Hotspare.
>
> I'd suggest you first try to reproduce the stall without ULE, while
> keeping all other parameters exactly the same.

Thanks for the idea Ivan, easy one to try. Just in the process of doing a update
to the latest 7.0 so will do than then try BSD if no change.

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland
In reply to this post by Ivan Voras

----- Original Message -----
From: "Ivan Voras" <[hidden email]>
>> The machine is running with ULE on 7.0 as mention using an Areca 1220
>> controller over 8 disks in RAID 6 + Hotspare.
>
> I'd suggest you first try to reproduce the stall without ULE, while
> keeping all other parameters exactly the same.

Ok tried with an updated 7 world / kernel as of this afternoon and with 4BSD
instead of ULE and no difference the machine still locks up with no activity
for anywhere from 20 to 30 seconds.

Here's a snapshot from top under cpu and io modes when the stall has occured
[top]
last pid:  1102;  load averages:  0.02,  0.08,  0.07                                           up 0+00:09:37  21:39:13
162 processes: 4 running, 145 sleeping, 13 waiting
CPU states:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6% idle
Mem: 60M Active, 19M Inact, 54M Wired, 56K Cache, 27M Buf, 3809M Free
Swap: 4096M Total, 4096M Free

  PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU COMMAND
   12 root        1 171 ki31     0K    16K RUN    0   8:59 97.90% idle: cpu0
   11 root        1 171 ki31     0K    16K RUN    1   8:57 95.80% idle: cpu1
 1102 root        1  -8    0  4752K  1256K physrd 1   0:01 19.64% newfs
    4 root        1  -8    -     0K    16K -      0   0:00  0.10% g_down
 1048 root        1  96    0  7656K  2544K CPU0   0   0:01  0.00% top
 1054 root        1  96    0  7656K  2348K CPU1   1   0:01  0.00% top
  863 root        1  96    0   131M 15768K select 0   0:00  0.00% httpd
 1055 root        1  96    0 32928K  4656K select 0   0:00  0.00% sshd


last pid:  1102;  load averages:  0.02,  0.08,  0.07                                           up 0+00:09:37  21:39:13
162 processes: 4 running, 145 sleeping, 13 waiting
CPU states:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6% idle
Mem: 60M Active, 19M Inact, 54M Wired, 56K Cache, 27M Buf, 3809M Free
Swap: 4096M Total, 4096M Free

  PID USERNAME   VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
   12 root          9    154      0      0      0      0   0.00% idle: cpu0
   11 root         28      5      0      0      0      0   0.00% idle: cpu1
 1102 root          5      0      0      0      0      0   0.00% newfs
    4 root         14      0      0      0      0      0   0.00% g_down
 1048 root          1      0      0      0      0      0   0.00% top
 1054 root          1      0      0      0      0      0   0.00% top
  863 root          1      0      0      0      0      0   0.00% httpd
[/top]

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

dieter-7
In message <008201c86388$fd159010$[hidden email]>, "Steven Hartland" writes:

> From: "Ivan Voras" <[hidden email]>
> >> The machine is running with ULE on 7.0 as mention using an Areca 1220
> >> controller over 8 disks in RAID 6 + Hotspare.
> >
> > I'd suggest you first try to reproduce the stall without ULE, while
> > keeping all other parameters exactly the same.
>
> Ok tried with an updated 7 world / kernel as of this afternoon and with 4BSD
> instead of ULE and no difference the machine still locks up with no activity
> for anywhere from 20 to 30 seconds.
>
> Here's a snapshot from top under cpu and io modes when the stall has occured
> [top]
> last pid:  1102;  load averages:  0.02,  0.08,  0.07                                           up 0+00:09:37  21:39:13
> 162 processes: 4 running, 145 sleeping, 13 waiting
> CPU states:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6% idle
> Mem: 60M Active, 19M Inact, 54M Wired, 56K Cache, 27M Buf, 3809M Free
> Swap: 4096M Total, 4096M Free
>
>   PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU COMMAND
>    12 root        1 171 ki31     0K    16K RUN    0   8:59 97.90% idle: cpu0
>    11 root        1 171 ki31     0K    16K RUN    1   8:57 95.80% idle: cpu1
>  1102 root        1  -8    0  4752K  1256K physrd 1   0:01 19.64% newfs
>     4 root        1  -8    -     0K    16K -      0   0:00  0.10% g_down
>  1048 root        1  96    0  7656K  2544K CPU0   0   0:01  0.00% top
>  1054 root        1  96    0  7656K  2348K CPU1   1   0:01  0.00% top
>   863 root        1  96    0   131M 15768K select 0   0:00  0.00% httpd
>  1055 root        1  96    0 32928K  4656K select 0   0:00  0.00% sshd
>
>
> last pid:  1102;  load averages:  0.02,  0.08,  0.07                                           up 0+00:09:37  21:39:13
> 162 processes: 4 running, 145 sleeping, 13 waiting
> CPU states:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6% idle
> Mem: 60M Active, 19M Inact, 54M Wired, 56K Cache, 27M Buf, 3809M Free
> Swap: 4096M Total, 4096M Free
>
>   PID USERNAME   VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
>    12 root          9    154      0      0      0      0   0.00% idle: cpu0
>    11 root         28      5      0      0      0      0   0.00% idle: cpu1
>  1102 root          5      0      0      0      0      0   0.00% newfs
>     4 root         14      0      0      0      0      0   0.00% g_down
>  1048 root          1      0      0      0      0      0   0.00% top
>  1054 root          1      0      0      0      0      0   0.00% top
>   863 root          1      0      0      0      0      0   0.00% httpd
> [/top]

What *exactly* do you mean by

> machine still locks up with no activity for anywhere from 20 to 30 seconds.

Is there disk activity? (e.g. activity light(s) flashing if you have them)

Does top continue to update the screen during the 20-30 seconds?

I'm thinking that newfs has queued up a bunch of disk i/o, and other
disk i/o gets locked out, but activities that don't require any disk i/o
(like top, once it is up and running) could continue.  Is that what is
happening?
_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland
----- Original Message -----
From: "Dieter" <[hidden email]>

> What *exactly* do you mean by
>
>> machine still locks up with no activity for anywhere from 20 to 30 seconds.
>
> Is there disk activity? (e.g. activity light(s) flashing if you have them)

Cant tell if there is disk activity its in a DC miles away ;)

> Does top continue to update the screen during the 20-30 seconds?
>
> I'm thinking that newfs has queued up a bunch of disk i/o, and other
> disk i/o gets locked out, but activities that don't require any disk i/o
> (like top, once it is up and running) could continue.  Is that what is
> happening?

No all sessions totally freeze. I have top set to 1 second refreshes and
the clock literally stops and then 20-30 seconds later continues. All
sessions are via ssh not X if that's of interest.

I could understand if IO to disk for other processes became slow but
everything including things like top just stop which is quite odd and
concerning.

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

dieter-7
> > What *exactly* do you mean by
> >
> >> machine still locks up with no activity for anywhere from 20 to 30 seconds.
> >
> > Is there disk activity? (e.g. activity light(s) flashing if you have them)
>
> Cant tell if there is disk activity its in a DC miles away ;)
>
> > Does top continue to update the screen during the 20-30 seconds?
> >
> > I'm thinking that newfs has queued up a bunch of disk i/o, and other
> > disk i/o gets locked out, but activities that don't require any disk i/o
> > (like top, once it is up and running) could continue.  Is that what is
> > happening?
>
> No all sessions totally freeze. I have top set to 1 second refreshes and
> the clock literally stops and then 20-30 seconds later continues.

Wow!

> All sessions are via ssh not X if that's of interest.
>
> I could understand if IO to disk for other processes became slow but
> everything including things like top just stop which is quite odd and
> concerning.

Ok, new idea.  Your disk activity is via the network, and your sessions
are via the network.  Could it be that something network related is saturated?
_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs + gstat locks entire machine for 20seconds

Steven Hartland
In reply to this post by dieter-7
The plot thickens.... This stall is not just related to newfs you have to
have gstat running as well. If I do the newfs without gstat running then
no stall occurs. As soon as Im running gstat while doing the newfs then
everything locks as described.

Running truss on gstat shows the issue / cause I believe but I dont
know what it means:-
[truss -o t.txt -p 61629 -d]
9.008933817 nanosleep({1.000000000})         = 0 (0x0)
9.008969017 gettimeofday({1201742426.147393},0x0) = 0 (0x0)
9.009009804 poll({0/POLLIN},1,0)         = 0 (0x0)
9.009040534 gettimeofday({1201742426.147465},0x0) = 0 (0x0)
9.009076852 clock_gettime(0,{1201742426.147501706}) = 0 (0x0)
9.009294477 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{ 0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
9.009335823 poll({0/POLLIN},1,0)         = 0 (0x0)
9.009387785 poll({0/POLLIN},1,0)         = 0 (0x0)
9.009457626 write(1,"\^[[4;11H 5\^[[6C2     32  467.8"...,213) = 213 (0xd5)
9.009488636 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
10.009930312 nanosleep({1.000000000})        = 0 (0x0)
10.009963836 gettimeofday({1201742427.148388},0x0) = 0 (0x0)
10.010005182 poll({0/POLLIN},1,0)        = 0 (0x0)
10.010036192 gettimeofday({1201742427.148461},0x0) = 0 (0x0)
10.010073068 clock_gettime(0,{1201742427.148497922}) = 0 (0x0)
10.010292369 mmap(0x801000000,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34376515584 (0x801000000)
10.010327569 __sysctl(0x7fffffffe6c0,0x2,0x7fffffffe650,0x7fffffffe6b8,0x800844970,0x11) = 0 (0x0)
25.052947791 __sysctl(0x7fffffffe650,0x3,0x801000000,0x7fffffffe720,0x0,0x0) = 0 (0x0)
25.054030610 munmap(0x801000000,1048576)     = 0 (0x0)
25.055022356 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{ 0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
25.055067892 poll({0/POLLIN},1,0)        = 0 (0x0)
25.055130470 poll({0/POLLIN},1,0)        = 0 (0x0)
25.055230203 write(1,"\^[[4;11H1\^[[7C4     64  203.4"...,203) = 203 (0xcb)
25.055263448 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
26.055866597 nanosleep({1.000000000})        = 0 (0x0)
26.055900400 gettimeofday({1201742443.194324},0x0) = 0 (0x0)
26.055940070 poll({0/POLLIN},1,0)        = 0 (0x0)
26.055969962 gettimeofday({1201742443.194394},0x0) = 0 (0x0)
26.056009073 clock_gettime(0,{1201742443.194433649}) = 0 (0x0)
26.056240388 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{ 0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
26.056280896 poll({0/POLLIN},1,0)        = 0 (0x0)
26.056334534 poll({0/POLLIN},1,0)        = 0 (0x0)
26.056420299 poll({0/POLLIN},1,0)        = 0 (0x0)
26.056485112 write(1,"\^[[1;6H6.046s  w: 1.000s\^[[4;5"...,305) = 305 (0x131)
26.056516121 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
27.056863372 nanosleep({1.000000000})        = 0 (0x0)
[/truss -o t.txt -p 61629 -d]

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs + gstat locks entire machine for 20seconds

mdtancsa
At 08:24 PM 1/30/2008, Steven Hartland wrote:
>The plot thickens.... This stall is not just related to newfs you have to
>have gstat running as well. If I do the newfs without gstat running then
>no stall occurs. As soon as Im running gstat while doing the newfs then
>everything locks as described.

Strange, I see the same thing sometimes.

While running

while true
do
date
sleep .5
done


Thu Jan 31 14:55:42 EST 2008
Thu Jan 31 14:55:42 EST 2008
Thu Jan 31 14:55:43 EST 2008
Thu Jan 31 14:55:43 EST 2008
Thu Jan 31 14:55:44 EST 2008
Thu Jan 31 14:55:44 EST 2008
Thu Jan 31 14:55:50 EST 2008
Thu Jan 31 14:55:50 EST 2008
Thu Jan 31 14:55:51 EST 2008
Thu Jan 31 14:55:51 EST 2008
Thu Jan 31 14:55:52 EST 2008
Thu Jan 31 14:55:52 EST 2008
Thu Jan 31 14:55:53 EST 2008
Thu Jan 31 14:55:53 EST 2008
Thu Jan 31 14:55:54 EST 2008

You can see it from 44 to 50 seconds,

This is AMD64

da0 at arcmsr0 bus 0 target 0 lun 0
da0: <Areca ARC-1210-VOL#00 R001> Fixed Direct Access SCSI-5 device
da0: 166.666MB/s transfers (83.333MHz DT, offset 32, 16bit)
da0: 305175MB (624999424 512 byte sectors: 255H 63S/T 38904C)

arcmsr0: <Areca SATA Host Adapter RAID Controller
 > mem 0xe8600000-0xe8600fff,0xe8000000-0xe83fffff irq 18 at device
14.0 on pci2
ARECA RAID ADAPTER0: Driver Version 1.20.00.15 2007-10-07
ARECA RAID ADAPTER0: FIRMWARE VERSION V1.43 2007-4-17
arcmsr0: [ITHREAD]



>Running truss on gstat shows the issue / cause I believe but I dont
>know what it means:-
>[truss -o t.txt -p 61629 -d]
>9.008933817 nanosleep({1.000000000})         = 0 (0x0)
>9.008969017 gettimeofday({1201742426.147393},0x0) = 0 (0x0)
>9.009009804 poll({0/POLLIN},1,0)         = 0 (0x0)
>9.009040534 gettimeofday({1201742426.147465},0x0) = 0 (0x0)
>9.009076852 clock_gettime(0,{1201742426.147501706}) = 0 (0x0)
>9.009294477 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{
>0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
>9.009335823 poll({0/POLLIN},1,0)         = 0 (0x0)
>9.009387785 poll({0/POLLIN},1,0)         = 0 (0x0)
>9.009457626 write(1,"\^[[4;11H 5\^[[6C2     32  467.8"...,213) = 213 (0xd5)
>9.009488636 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
>10.009930312 nanosleep({1.000000000})        = 0 (0x0)
>10.009963836 gettimeofday({1201742427.148388},0x0) = 0 (0x0)
>10.010005182 poll({0/POLLIN},1,0)        = 0 (0x0)
>10.010036192 gettimeofday({1201742427.148461},0x0) = 0 (0x0)
>10.010073068 clock_gettime(0,{1201742427.148497922}) = 0 (0x0)
>10.010292369
>mmap(0x801000000,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0)
>= 34376515584 (0x801000000)
>10.010327569
>__sysctl(0x7fffffffe6c0,0x2,0x7fffffffe650,0x7fffffffe6b8,0x800844970,0x11)
>= 0 (0x0)
>25.052947791
>__sysctl(0x7fffffffe650,0x3,0x801000000,0x7fffffffe720,0x0,0x0) = 0 (0x0)
>25.054030610 munmap(0x801000000,1048576)     = 0 (0x0)
>25.055022356 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{
>0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
>25.055067892 poll({0/POLLIN},1,0)        = 0 (0x0)
>25.055130470 poll({0/POLLIN},1,0)        = 0 (0x0)
>25.055230203 write(1,"\^[[4;11H1\^[[7C4     64  203.4"...,203) = 203 (0xcb)
>25.055263448 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
>26.055866597 nanosleep({1.000000000})        = 0 (0x0)
>26.055900400 gettimeofday({1201742443.194324},0x0) = 0 (0x0)
>26.055940070 poll({0/POLLIN},1,0)        = 0 (0x0)
>26.055969962 gettimeofday({1201742443.194394},0x0) = 0 (0x0)
>26.056009073 clock_gettime(0,{1201742443.194433649}) = 0 (0x0)
>26.056240388 sigaction(SIGTSTP,{ SIG_IGN SA_RESTART ss_t },{
>0x800cb2470 SA_RESTART ss_t }) = 0 (0x0)
>26.056280896 poll({0/POLLIN},1,0)        = 0 (0x0)
>26.056334534 poll({0/POLLIN},1,0)        = 0 (0x0)
>26.056420299 poll({0/POLLIN},1,0)        = 0 (0x0)
>26.056485112 write(1,"\^[[1;6H6.046s  w: 1.000s\^[[4;5"...,305) = 305 (0x131)
>26.056516121 sigaction(SIGTSTP,{ 0x800cb2470 SA_RESTART ss_t },0x0) = 0 (0x0)
>27.056863372 nanosleep({1.000000000})        = 0 (0x0)
>[/truss -o t.txt -p 61629 -d]
>
>================================================
>This e.mail is private and confidential between Multiplay (UK) Ltd.
>and the person or entity to whom it is addressed. In the event of
>misdirection, the recipient is prohibited from using, copying,
>printing or otherwise disseminating it or any information contained in it.
>In the event of misdirection, illegible or incomplete transmission
>please telephone +44 845 868 1337
>or return the E.mail to [hidden email].
>
>_______________________________________________
>[hidden email] mailing list
>http://lists.freebsd.org/mailman/listinfo/freebsd-performance
>To unsubscribe, send any mail to "[hidden email]"

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Eric Anderson-13
In reply to this post by dieter-7
Dieter wrote:

>>> What *exactly* do you mean by
>>>
>>>> machine still locks up with no activity for anywhere from 20 to 30 seconds.
>>> Is there disk activity? (e.g. activity light(s) flashing if you have them)
>> Cant tell if there is disk activity its in a DC miles away ;)
>>
>>> Does top continue to update the screen during the 20-30 seconds?
>>>
>>> I'm thinking that newfs has queued up a bunch of disk i/o, and other
>>> disk i/o gets locked out, but activities that don't require any disk i/o
>>> (like top, once it is up and running) could continue.  Is that what is
>>> happening?
>> No all sessions totally freeze. I have top set to 1 second refreshes and
>> the clock literally stops and then 20-30 seconds later continues.
>
> Wow!
>
>> All sessions are via ssh not X if that's of interest.
>>
>> I could understand if IO to disk for other processes became slow but
>> everything including things like top just stop which is quite odd and
>> concerning.
>
> Ok, new idea.  Your disk activity is via the network, and your sessions
> are via the network.  Could it be that something network related is saturated?


I saw this once before, a long time back, and every time I went through
a debugging session, it came to some kind of lock on the sysctl tree
with regards to the geom info (maybe the XML kind of tree dump or
something).  I don't recall all the details, but it was something like
that.

Eric

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland

----- Original Message -----
From: "Eric Anderson" <[hidden email]>

> I saw this once before, a long time back, and every time I went through a debugging session, it came to some kind of lock on the
> sysctl tree with regards to the geom info (maybe the XML kind of tree dump or something).  I don't recall all the details, but
> it was something like that.

Yep thats where I've traced it to its requesting: kern.geom.confxml

Which does:-
static int
sysctl_kern_geom_confxml(SYSCTL_HANDLER_ARGS)
{
    int error;
    struct sbuf *sb;

    sb = sbuf_new(NULL, NULL, 0, SBUF_AUTOEXTEND);
    g_waitfor_event(g_confxml, sb, M_WAITOK, NULL);
    error = SYSCTL_OUT(req, sbuf_data(sb), sbuf_len(sb) + 1);
    sbuf_delete(sb);
    return error;
}

What I dont understand is why this would lock the entire machine.

I've enabled LOCK_PROFILING and reran and I get the following which
seems to indicate the culpret is: SYSCTL_LOCK()

>From what I can tell g_waitfor_event is returning EAGAIN for a large
amount of time which means we get stuck in:-
userland_sysctl
...
    SYSCTL_LOCK();

    do {
        req.oldidx = 0;
        req.newidx = 0;
        error = sysctl_root(0, name, namelen, &req);
    } while (error == EAGAIN);

    if (req.lock == REQ_WIRED && req.validlen > 0)
        vsunlock(req.oldptr, req.validlen);

    SYSCTL_UNLOCK();
...

The only reason I can see for returning EAGAIN is g_destroy_geom
calling g_cancel_event

To confirm this wasnt related to anything that top is doing and
we are seeing a total lockup I used:
sh -c 'while [ 1 ]; do sleep 1; date; done'
Fri Feb  1 06:04:47 GMT 2008
Fri Feb  1 06:04:48 GMT 2008
Fri Feb  1 06:04:49 GMT 2008 <= Lockup
Fri Feb  1 06:05:16 GMT 2008 <= Recover
Fri Feb  1 06:05:17 GMT 2008
Fri Feb  1 06:05:18 GMT 2008


Enabling geom debugging I get:-
Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0, 0xffffff00010e6100, 2, 0)
Feb  1 06:04:45 geomtest kernel: ref 0xffffff00010e6100
Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0, 0xffffff00014e6700, 2, 0)
Feb  1 06:04:45 geomtest kernel: ref 0xffffff00014e6700
Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270, 0xffffff00010e6100, 2, 0)
Feb  1 06:04:49 geomtest kernel: ref 0xffffff00010e6100
Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270, 0xffffff00014e6700, 2, 0)
Feb  1 06:04:49 geomtest kernel: ref 0xffffff00014e6700
Feb  1 06:04:49 geomtest kernel: mbr_taste(MBR,da0s3)
Feb  1 06:04:49 geomtest kernel: g_mbrext_taste(MBREXT,da0s3)
Feb  1 06:04:49 geomtest kernel: g_slice_spoiled(0xffffff0001b27180/da0s3)
Feb  1 06:04:49 geomtest kernel: g_wither_geom(0xffffff0001a33c00(da0s3))
Feb  1 06:04:49 geomtest kernel: g_part_taste(PART,da0s3)
Feb  1 06:04:56 geomtest kernel: g_post_event_x(0xffffffff80235b10, 0xffffff000144a9c0, 2, 262144)
Feb  1 06:05:00 geomtest kernel: g_wither_geom(0xffffff000158b300(da0s3))
Feb  1 06:05:00 geomtest kernel:
Feb  1 06:05:00 geomtest kernel: g_label_taste(LABEL, da0s3)
Feb  1 06:05:00 geomtest kernel:
Feb  1 06:05:16 geomtest kernel: GEOM_LABEL[1]: MSDOSFS: da0s3: FAT32 volume not valid.
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b23980)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b23980)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001b4be00(label:taste))
Feb  1 06:05:16 geomtest kernel: mbr_taste(MBR,da0s3g)
Feb  1 06:05:16 geomtest kernel: g_slice_spoiled(0xffffff0001a3c280/da0s3g)
Feb  1 06:05:16 geomtest kernel: g_wither_geom(0xffffff0001b4b600(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_mbrext_taste(MBREXT,da0s3g)
Feb  1 06:05:16 geomtest kernel: bsd_taste(BSD,da0s3g)
Feb  1 06:05:16 geomtest kernel: g_slice_spoiled(0xffffff0001b27200/da0s3g)
Feb  1 06:05:16 geomtest kernel: g_wither_geom(0xffffff0001504c00(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_part_taste(PART,da0s3g)
Feb  1 06:05:16 geomtest kernel: g_wither_geom(0xffffff0001527100(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_label_taste(LABEL, da0s3g)
Feb  1 06:05:16 geomtest kernel: GEOM_LABEL[1]: UFS2 file system detected on da0s3g.
Feb  1 06:05:16 geomtest kernel: GEOM_LABEL[1]: MSDOSFS: da0s3g: no FAT signature found.
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b23a80)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b23a80)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001b4be00(label:taste))
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001a3c280)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001a3c280)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001b4b600(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b27180)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b27180)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001a33c00(da0s3))
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b27200)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b27200)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001504c00(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001adc580)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001adc580)
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff0001527100(da0s3g))
Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b23b00)
Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b23b00)
Feb  1 06:05:16 geomtest kernel:
Feb  1 06:05:16 geomtest kernel: g_destroy_geom(0xffffff000158b300(da0s3))

So after all that I can see why the sysctl call is taking
so long to complete but the burning question is why does
the entire system lock because of this? What else is
waiting on the sysctl lock which is so critical?


debug.lock.prof.stats:
   max        total   wait_total       count   avg wait_avg     cnt_hold     cnt_lock name
153585139    181478925            0         112 1620347     0            0            0 kern/vfs_subr.c:2062 (lockmgr:ufs)
26298436     26298513     23195820          24 1095771 966492            1            1 kern/kern_sysctl.c:1396 (sx:sysctl lock)
2396114      5604484            0         596  9403     0            0            0 sys/buf.h:280 (lockmgr:bufwait)
   214        76577         1837       12490     6     0          185          280 kern/subr_sleepqueue.c:232 (spin mutex:sleepq
chain)
     1        34126            2       30415     1     0            2            1 kern/kern_clock.c:224 (spin mutex:sched lock 1)
     2        34069            5       30415     1     0            3            2 kern/kern_clock.c:224 (spin mutex:sched lock 0)
     1        34067            0       30415     1     0            0            0 kern/kern_clock.c:264 (spin mutex:callout)
    54        23629            1        4122     5     0            6            1 kern/uipc_socket.c:2468 (sleep mutex:so_snd)
    34        22599            0        9232     2     0            0            0 amd64/amd64/pmap.c:935 (sleep mutex:vm page
queue mutex)
    34        22573            0        9232     2     0            0            0 amd64/amd64/pmap.c:936 (sleep mutex:pmap)
   121        20165            0         586    34     0            0            0 kern/uipc_sockbuf.c:145 (sx:so_snd_sx)
    50        19229           38        9401     2     0            3            3 geom/geom_io.c:68 (sleep mutex:bio queue)
   117        16281            0         586    27     0           17            0 netinet/tcp_usrreq.c:781 (sleep mutex:inp)
    50        14954          245       11968     1     0           15           62 kern/kern_conf.c:69 (sleep mutex:cdev)
    52        13599            0        4122     3     0            0            0 kern/uipc_socket.c:2469 (sleep mutex:so_rcv)
   227        11779            0         625    18     0            1            0 cam/cam_xpt.c:7153 (sleep mutex:arcmsr Q buffer
lock)
    40        11779            0         639    18     0           50            0 kern/kern_conf.c:372 (sleep mutex:Giant)
    52        11201          219        3536     3     0            3           47 kern/kern_conf.c:384 (sleep mutex:Giant)
    11        10888            0        1770     6     0            0            0 kern/subr_taskqueue.c:71 (spin
mutex:fast_taskqueue)
    41        10866            0        3041     3     0            0            0 netinet/tcp_subr.c:1426 (sleep mutex:isn_mtx)
    50         9858            5        8243     1     0            1            3 kern/sys_generic.c:1079 (sleep mutex:sellck)
     5         9545            7        3416     2     0            3            2 kern/sched_ule.c:1872 (spin mutex:sched lock 0)
     2         9029          677        7356     1     0          103          319 kern/kern_timeout.c:419 (spin mutex:callout)
    52         8916            0        1813     4     0            1            0 kern/sys_generic.c:759 (sleep mutex:sellck)
   222         8318            0         625    13     0            0            0 geom/geom_disk.c:198 (sleep mutex:g_disk_done)
     1         7843            3        6407     1     0            3            2 kern/kern_timeout.c:296 (spin mutex:callout)
     5         7240           17        5090     1     0            5            7 kern/kern_switch.c:182 (spin mutex:sched lock
0)
    64         6940           58        1276     5     0            0            3 kern/kern_timeout.c:241 (sleep mutex:Giant)
     5         6924         2880        1730     4     1            2         1715 amd64/amd64/mp_machdep.c:966 (spin mutex:sched
lock 0)
    13         6845            0         623    10     0            0            0 amd64/amd64/mp_machdep.c:845 (spin mutex:smp
rendezvous)
    53         6279            0        1766     3     0            0            0 kern/sys_pipe.c:1331 (sleep mutex:pipe mutex)
     5         6063           93        4189     1     0            2           27 kern/kern_intr.c:1131 (spin mutex:sched lock 0)
    15         5910           25         660     8     0            7           10 kern/sys_generic.c:1127 (sleep mutex:sellck)
    56         5290          727         357    14     2            0           17 netinet/tcp_input.c:479 (sleep mutex:inp)
   144         5264            0         116    45     0            0            0 vm/vm_map.c:3111 (sx:user map)
     7         4971           25        1552     3     0            9           11 kern/sched_ule.c:1872 (spin mutex:sched lock 1)
    11         4959            0         625     7     0            0            0 dev/arcmsr/arcmsr.c:1129 (sleep mutex:arcmsr Q
buffer lock)
   210         4901           56        3436     1     0            9           27 kern/sched_ule.c:979 (spin mutex:sched lock 0)
    69         4899            0         357    13     0            0            0 netinet/tcp_input.c:400 (sleep mutex:tcp)
     1         4698            0        4045     1     0            0            0 kern/kern_clock.c:412 (spin mutex:sched lock 1)
     1         4697            0        4189     1     0            1            0 kern/kern_intr.c:706 (spin mutex:sched lock 0)
     1         4696            0        4184     1     0            0            0 kern/kern_timeout.c:191 (spin mutex:callout)
    45         4604            0         591     7     0            6            0 kern/vfs_bio.c:3790 (sleep mutex:bdone lock)
     2         4550            3        4045     1     0            0            1 kern/kern_clock.c:412 (spin mutex:sched lock 0)
    53         4384            0        1228     3     0            0            0 kern/sys_generic.c:750 (sleep mutex:sellck)
     2         4189            3        3392     1     0            1            2 kern/subr_sleepqueue.c:331 (spin mutex:sched
lock 0)
  3695         4042            0           4  1010     0            0            0 kern/vfs_vnops.c:515 (lockmgr:ufs)
     8         3891            0         645     6     0            0            0 kern/subr_sleepqueue.c:409 (spin mutex:sleepq
chain)
    10         3773            0        3103     1     0            1            0 kern/vfs_bio.c:3002 (sleep mutex:bdone lock)
    55         3323           22         634     5     0            4            7 kern/kern_mutex.c:141 (sleep mutex:sellck)
    50         3188            0        2469     1     0            0            0 kern/kern_descrip.c:2139 (sleep mutex:sleep
mtxpool)
  1853         3083            0           4   770     0            0            0 kern/vfs_subr.c:1665 (lockmgr:syncer)
     6         3074            0        1310     2     0            0            0 kern/kern_lock.c:200 (sleep mutex:lockbuilder
mtxpool)
    10         3003            0         645     4     0            0            0 kern/subr_sleepqueue.c:390 (sleep mutex:process
lock)
    32         2991            0        2448     1     0            0            0 kern/kern_descrip.c:2007 (sleep mutex:sleep
mtxpool)
    50         2852            0        2401     1     0            0            0 kern/kern_sig.c:996 (sleep mutex:process lock)
    94         2458            0         589     4     0            0            0 dev/em/if_em.c:980 (sleep mutex:em0)
    54         2358            6         592     3     0            0            3 kern/kern_conf.c:360 (sleep mutex:Giant)
     1         2343           35        1547     1     0           20           20 kern/subr_sleepqueue.c:331 (spin mutex:sched
lock 1)
     2         2272           98        1540     1     0          238           39 kern/sched_ule.c:979 (spin mutex:sched lock 1)
     1         2214            0        1897     1     0            0            0 kern/subr_sleepqueue.c:595 (spin mutex:sched
lock 0)
     1         2194            4        1329     1     0            2            2 kern/kern_timeout.c:500 (spin mutex:callout)
     1         2189           33        1526     1     0            0            4 kern/subr_sleepqueue.c:800 (spin mutex:sleepq
chain)
     5         2160         1959        1173     1     1            0         1168 amd64/amd64/mp_machdep.c:966 (spin mutex:sched
lock 1)
     1         2158            1        1660     1     0            0            1 kern/sys_generic.c:753 (spin mutex:sched lock
0)
     8         1972            0         248     7     0            0            0 kern/kern_timeout.c:241 (sleep mutex:process
lock)
     6         1968           11        1245     1     0            2            5 kern/kern_intr.c:1131 (spin mutex:sched lock 1)


================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Ivan Voras
Steven Hartland wrote:

> Yep thats where I've traced it to its requesting: kern.geom.confxml
>
> Which does:-
> static int
> sysctl_kern_geom_confxml(SYSCTL_HANDLER_ARGS)
> {
>    int error;
>    struct sbuf *sb;
>
>    sb = sbuf_new(NULL, NULL, 0, SBUF_AUTOEXTEND);
>    g_waitfor_event(g_confxml, sb, M_WAITOK, NULL);
>    error = SYSCTL_OUT(req, sbuf_data(sb), sbuf_len(sb) + 1);
>    sbuf_delete(sb);
>    return error;
> }
>
> What I dont understand is why this would lock the entire machine.
>
> I've enabled LOCK_PROFILING and reran and I get the following which
> seems to indicate the culpret is: SYSCTL_LOCK()
>
>> From what I can tell g_waitfor_event is returning EAGAIN for a large
> amount of time which means we get stuck in:-
> userland_sysctl
> ...
>    SYSCTL_LOCK();
>
>    do {
>        req.oldidx = 0;
>        req.newidx = 0;
>        error = sysctl_root(0, name, namelen, &req);
>    } while (error == EAGAIN);
>
>    if (req.lock == REQ_WIRED && req.validlen > 0)
>        vsunlock(req.oldptr, req.validlen);
>
>    SYSCTL_UNLOCK();
> ...
>
> The only reason I can see for returning EAGAIN is g_destroy_geom
> calling g_cancel_event
>
> To confirm this wasnt related to anything that top is doing and
> we are seeing a total lockup I used:
> sh -c 'while [ 1 ]; do sleep 1; date; done'
> Fri Feb  1 06:04:47 GMT 2008
> Fri Feb  1 06:04:48 GMT 2008
> Fri Feb  1 06:04:49 GMT 2008 <= Lockup
> Fri Feb  1 06:05:16 GMT 2008 <= Recover
> Fri Feb  1 06:05:17 GMT 2008
> Fri Feb  1 06:05:18 GMT 2008
>
>
> Enabling geom debugging I get:-
> Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0,
> 0xffffff00010e6100, 2, 0)
> Feb  1 06:04:45 geomtest kernel: ref 0xffffff00010e6100
> Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0,
> 0xffffff00014e6700, 2, 0)
> Feb  1 06:04:45 geomtest kernel: ref 0xffffff00014e6700
> Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270,
> 0xffffff00010e6100, 2, 0)
> Feb  1 06:04:49 geomtest kernel: ref 0xffffff00010e6100
> Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270,
> 0xffffff00014e6700, 2, 0)
> Feb  1 06:04:49 geomtest kernel: ref 0xffffff00014e6700
> Feb  1 06:04:49 geomtest kernel: mbr_taste(MBR,da0s3)
> Feb  1 06:04:49 geomtest kernel: g_mbrext_taste(MBREXT,da0s3)
> Feb  1 06:04:49 geomtest kernel: g_slice_spoiled(0xffffff0001b27180/da0s3)
> Feb  1 06:04:49 geomtest kernel: g_wither_geom(0xffffff0001a33c00(da0s3))
> Feb  1 06:04:49 geomtest kernel: g_part_taste(PART,da0s3)
> Feb  1 06:04:56 geomtest kernel: g_post_event_x(0xffffffff80235b10,
> 0xffffff000144a9c0, 2, 262144)
> Feb  1 06:05:00 geomtest kernel: g_wither_geom(0xffffff000158b300(da0s3))
> Feb  1 06:05:00 geomtest kernel:
> Feb  1 06:05:00 geomtest kernel: g_label_taste(LABEL, da0s3)
> Feb  1 06:05:00 geomtest kernel:
> Feb  1 06:05:16 geomtest kernel: GEOM_LABEL[1]: MSDOSFS: da0s3: FAT32
> volume not valid.
> Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b23980)
> Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b23980)
> Feb  1 06:05:16 geomtest kernel:

> So after all that I can see why the sysctl call is taking
> so long to complete but the burning question is why does

Can you explain - I don't see it :) Do you mean to say there's a
contention for sysctl lock between geom_confxml and g_waitfor_event or
that geom_label tasting has something to do with it?

> the entire system lock because of this? What else is
> waiting on the sysctl lock which is so critical?

What I do know is that sysctl is GIANT-locked, which is also used by
some parts of device handling infrastructure (dead_cdevsw), the USB
stack, and can creep itself in the timer via swi_sched in
subr_taskqueue.c:303. I cannot say for sure that's what happening here,
but they are possibilities.

If you can provoke this reliably, I think there is a (old!) patch for
removing sysctl from under the Giant lock that you could try.


signature.asc (196 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Eric Anderson-13
In reply to this post by Steven Hartland
Steven Hartland wrote:

>
> ----- Original Message ----- From: "Eric Anderson" <[hidden email]>
>
>> I saw this once before, a long time back, and every time I went
>> through a debugging session, it came to some kind of lock on the
>> sysctl tree with regards to the geom info (maybe the XML kind of tree
>> dump or something).  I don't recall all the details, but it was
>> something like that.
>
> Yep thats where I've traced it to its requesting: kern.geom.confxml
>
> Which does:-
> static int
> sysctl_kern_geom_confxml(SYSCTL_HANDLER_ARGS)
> {
>    int error;
>    struct sbuf *sb;
>
>    sb = sbuf_new(NULL, NULL, 0, SBUF_AUTOEXTEND);
>    g_waitfor_event(g_confxml, sb, M_WAITOK, NULL);
>    error = SYSCTL_OUT(req, sbuf_data(sb), sbuf_len(sb) + 1);
>    sbuf_delete(sb);
>    return error;
> }
>
> What I dont understand is why this would lock the entire machine.
>
> I've enabled LOCK_PROFILING and reran and I get the following which
> seems to indicate the culpret is: SYSCTL_LOCK()
>
>  From what I can tell g_waitfor_event is returning EAGAIN for a large
> amount of time which means we get stuck in:-
> userland_sysctl
> ...
>    SYSCTL_LOCK();
>
>    do {
>        req.oldidx = 0;
>        req.newidx = 0;
>        error = sysctl_root(0, name, namelen, &req);
>    } while (error == EAGAIN);
>
>    if (req.lock == REQ_WIRED && req.validlen > 0)
>        vsunlock(req.oldptr, req.validlen);
>
>    SYSCTL_UNLOCK();
> ...
>
> The only reason I can see for returning EAGAIN is g_destroy_geom
> calling g_cancel_event


Wait - if it returns EAGAIN for a while, then look at that code above.
It will hold the sysctl lock for some indefinite amount of time.  Maybe
it should look like this instead:


    do {
        SYSCTL_LOCK();
        req.oldidx = 0;
        req.newidx = 0;
        error = sysctl_root(0, name, namelen, &req);
        SYSCTL_UNLOCK();
    } while (error == EAGAIN);

    if (req.lock == REQ_WIRED && req.validlen > 0)
        vsunlock(req.oldptr, req.validlen);


Can you try that?

Eric

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland
In reply to this post by Ivan Voras
----- Original Message -----
From: "Ivan Voras" <[hidden email]>
...

>> geom debugging I get:-
>> Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0,
>> 0xffffff00010e6100, 2, 0)
>> Feb  1 06:04:45 geomtest kernel: ref 0xffffff00010e6100
>> Feb  1 06:04:45 geomtest kernel: g_post_event_x(0xffffffff802394c0,
>> 0xffffff00014e6700, 2, 0)
>> Feb  1 06:04:45 geomtest kernel: ref 0xffffff00014e6700
>> Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270,
>> 0xffffff00010e6100, 2, 0)
>> Feb  1 06:04:49 geomtest kernel: ref 0xffffff00010e6100
>> Feb  1 06:04:49 geomtest kernel: g_post_event_x(0xffffffff80239270,
>> 0xffffff00014e6700, 2, 0)
>> Feb  1 06:04:49 geomtest kernel: ref 0xffffff00014e6700
>> Feb  1 06:04:49 geomtest kernel: mbr_taste(MBR,da0s3)
>> Feb  1 06:04:49 geomtest kernel: g_mbrext_taste(MBREXT,da0s3)
>> Feb  1 06:04:49 geomtest kernel: g_slice_spoiled(0xffffff0001b27180/da0s3)
>> Feb  1 06:04:49 geomtest kernel: g_wither_geom(0xffffff0001a33c00(da0s3))
>> Feb  1 06:04:49 geomtest kernel: g_part_taste(PART,da0s3)
>> Feb  1 06:04:56 geomtest kernel: g_post_event_x(0xffffffff80235b10,
>> 0xffffff000144a9c0, 2, 262144)
>> Feb  1 06:05:00 geomtest kernel: g_wither_geom(0xffffff000158b300(da0s3))
>> Feb  1 06:05:00 geomtest kernel:
>> Feb  1 06:05:00 geomtest kernel: g_label_taste(LABEL, da0s3)
>> Feb  1 06:05:00 geomtest kernel:
>> Feb  1 06:05:16 geomtest kernel: GEOM_LABEL[1]: MSDOSFS: da0s3: FAT32
>> volume not valid.
>> Feb  1 06:05:16 geomtest kernel: g_detach(0xffffff0001b23980)
>> Feb  1 06:05:16 geomtest kernel: g_destroy_consumer(0xffffff0001b23980)
>> Feb  1 06:05:16 geomtest kernel:
>
>> So after all that I can see why the sysctl call is taking
>> so long to complete but the burning question is why does
>
> Can you explain - I don't see it :) Do you mean to say there's a
> contention for sysctl lock between geom_confxml and g_waitfor_event or
> that geom_label tasting has something to do with it?

Nope what I belive to be happening is this sysctl_kern_geom_confxml which
is called while SYSCTL_LOCK is held from userland_sysctl returns EAGAIN
for a considerable period while newfs runs.

>> the entire system lock because of this? What else is
>> waiting on the sysctl lock which is so critical?
>
> What I do know is that sysctl is GIANT-locked, which is also used by
> some parts of device handling infrastructure (dead_cdevsw), the USB
> stack, and can creep itself in the timer via swi_sched in
> subr_taskqueue.c:303. I cannot say for sure that's what happening here,
> but they are possibilities.
>
> If you can provoke this reliably, I think there is a (old!) patch for
> removing sysctl from under the Giant lock that you could try.

Yes this is 100% reproducable and I'm beginning to suspect this issue may
the cause of the regular pauses on our hosting machines so it might have
further reaching effects than just this one example.

If SYSCTL_LOCK is indeed GIANT locked then it might explain why its effect
is so pronounced.

Tried ADAPTIVE_SX as test to see if that helped as the sysctl lock is
and sx but didnt help

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland
In reply to this post by Eric Anderson-13
----- Original Message -----
From: "Eric Anderson" <[hidden email]>

> Wait - if it returns EAGAIN for a while, then look at that code above.
> It will hold the sysctl lock for some indefinite amount of time.  Maybe
> it should look like this instead:
>
>
>    do {
>        SYSCTL_LOCK();
>        req.oldidx = 0;
>        req.newidx = 0;
>        error = sysctl_root(0, name, namelen, &req);
>        SYSCTL_UNLOCK();
>    } while (error == EAGAIN);
>
>    if (req.lock == REQ_WIRED && req.validlen > 0)
>        vsunlock(req.oldptr, req.validlen);
>

Tried no difference unfortunately, possibly its give the closeness
of the lock unlock its just reacquiring the lock straight after releasing
it hence not giving the other thread chance to run / obtain the lock?

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

Steven Hartland

----- Original Message -----
From: "Steven Hartland" <[hidden email]>


> ----- Original Message -----
> From: "Eric Anderson" <[hidden email]>
>> Wait - if it returns EAGAIN for a while, then look at that code above.
>> It will hold the sysctl lock for some indefinite amount of time.  Maybe
>> it should look like this instead:
>>
>>
>>    do {
>>        SYSCTL_LOCK();
>>        req.oldidx = 0;
>>        req.newidx = 0;
>>        error = sysctl_root(0, name, namelen, &req);
>>        SYSCTL_UNLOCK();
>>    } while (error == EAGAIN);
>>
>>    if (req.lock == REQ_WIRED && req.validlen > 0)
>>        vsunlock(req.oldptr, req.validlen);
>>
>
> Tried no difference unfortunately, possibly its give the closeness
> of the lock unlock its just reacquiring the lock straight after releasing
> it hence not giving the other thread chance to run / obtain the lock?

In an attempt to prove this is in fact the issue I've tried with the
locking around this code removed, yes dangerous but just as a test :)
It does indeed prevent the extended lockup so this is the right area.

    Regards
    Steve

================================================
This e.mail is private and confidential between Multiplay (UK) Ltd. and the person or entity to whom it is addressed. In the event of misdirection, the recipient is prohibited from using, copying, printing or otherwise disseminating it or any information contained in it.

In the event of misdirection, illegible or incomplete transmission please telephone +44 845 868 1337
or return the E.mail to [hidden email].

_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: newfs locks entire machine for 20seconds

dieter-7
> >> Wait - if it returns EAGAIN for a while, then look at that code above.
> >> It will hold the sysctl lock for some indefinite amount of time.  Maybe
> >> it should look like this instead:
> >>
> >>
> >>    do {
> >>        SYSCTL_LOCK();
> >>        req.oldidx = 0;
> >>        req.newidx = 0;
> >>        error = sysctl_root(0, name, namelen, &req);
> >>        SYSCTL_UNLOCK();
> >>    } while (error == EAGAIN);
> >>
> >>    if (req.lock == REQ_WIRED && req.validlen > 0)
> >>        vsunlock(req.oldptr, req.validlen);
> >>
> >
> > Tried no difference unfortunately, possibly its give the closeness
> > of the lock unlock its just reacquiring the lock straight after releasing
> > it hence not giving the other thread chance to run / obtain the lock?
>
> In an attempt to prove this is in fact the issue I've tried with the
> locking around this code removed, yes dangerous but just as a test :)
> It does indeed prevent the extended lockup so this is the right area.

Would adding a call to cpu_switch() be appropriate here?
_______________________________________________
[hidden email] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-performance
To unsubscribe, send any mail to "[hidden email]"