WoooHooo. The cat is out of the bag/box.
I didn't change anything, but the very next shutdown captured the delayed tuned exit.
I have attached the raw (.log) and processed (.txt) versions of the log.
I am not sure what to look for, but subsequent shutdowns show the delayed tuned exit at different points in the sequence each time.
The length of time to shut down (when there is no tuned delay) varies from about 1.6 seconds to 15 seconds. I wonder if there is interference from the other KVM guests.
I will try an install on a bare metal machine to see if I can find more consistent timings.
Cheers
Bill
-----Original message-----
> From:Bill Maidment <[log in to unmask]>
> Sent: Sunday 22nd January 2017 10:55
> To: David Sommerseth <[log in to unmask]>; [log in to unmask]
> Subject: RE: SL7.3RC2 shutdown slow
>
> Thanks for your patience, David, and for the very useful training.
>
> OK. I like a challenge!
> I found that the debugfs was already mounted and that I had missed copying the diagnose.shutdown script into /usr/lib/systemd/system-shutdown/
>
> Now I have a log file which shows the sequence of the shutdown process and a "Schrodinger's cat" conundrum (I prefer the term Schrondinbug, because I like cats).
> The tuned process is halted about 1.1 seconds into the shutdown (see attached). So now I know how it should work.
> I suppose it's now a matter of throwing in some other random processes to make it not work again????
> Any suggestions?
>
> Cheers
> Bill
>
> -----Original message-----
> > From:David Sommerseth <[log in to unmask]>
> > Sent: Sunday 22nd January 2017 7:38
> > To: Bill Maidment <[log in to unmask]>; [log in to unmask]
> > Subject: Re: SL7.3RC2 shutdown slow
> >
> > On 21/01/17 05:16, Bill Maidment wrote:
> > > He! He! He!
> > > I've installed the shutdown diagnostic and on reboot there is no delay on shutdown!
> > > Unfortunately, ftrace was not installed, so I couldn't analyse what was not happening.
> >
> > Ftrace is a kernel component which is enabled by default. But you need
> > to have the debugfs mounted at the appropriate place. For more info:
> > <https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/7/html/Developer_Guide/ftrace.html>
> >
> > > I removed the diagnostic and the shutdown delay returned.
> > > So it seems that the more you search for something, the more it goes away.
> > > I am out of my depth now, so I'll leave this issue as an exercise for the brave.
> >
> > Oh, those are "funny" ... and they are usually called Heisenbugs ...
> > <https://en.wikipedia.org/wiki/Heisenbug>
> >
> > I would then look more carefully at what this shutdown diagnostics
> > enables under the hood ... and see if you can figure out what triggers
> > the delay to disappear. Or if it is just as simple as something being
> > shutdown in the wrong order and a delay somewhere avoids a little
> > timeout causing the delay you see.
> >
> >
> > --
> > kind regards,
> >
> > David Sommerseth
> >
> >
> > > -----Original message-----
> > >> From:Bill Maidment <[log in to unmask]>
> > >> Sent: Saturday 21st January 2017 7:48
> > >> To: David Sommerseth <[log in to unmask]>; [log in to unmask]
> > >> Subject: RE: SL7.3RC2 shutdown slow
> > >>
> > >> David
> > >> Thanks for the info. However, this only deals with booting. My issue is with shutdown.
> > >> Your other email points to a shutdown diagnostic, so I'll try that, but I'm a bit wary of that not being a stable process.
> > >>
> > >>
> > >> -----Original message-----
> > >>> From:David Sommerseth <[log in to unmask]>
> > >>> Sent: Saturday 21st January 2017 2:11
> > >>> To: Bill Maidment <[log in to unmask]>; [log in to unmask]
> > >>> Subject: Re: SL7.3RC2 shutdown slow
> > >>>
> > >>> On 20/01/17 09:11, Bill Maidment wrote:
> > >>>> Update.....
> > >>>>
> > >>>> After shutting down several times everything seems to have settled
> > >>>> down and there is no delay. Maybe I'm too impatient. Or something
> > >>>> needed time to stabilize.
> > >>>
> > >>> When you experience such issues, systemd does have a good way to help
> > >>> point fingers at why the boot process lags ...
> > >>>
> > >>> # systemd-analyze blame
> > >>>
> > >>> Replace 'blame' with 'plot', and you'll get an SVG file with a graphical
> > >>> presentation of the boot process, in which order unit files started,
> > >>> when they started and how much time each of them needed. Or use 'dot'
> > >>> to get a similar view in the dot(1) format.
> > >>>
> > >>>
> > >>> --
> > >>> kind regards,
> > >>>
> > >>> David Sommerseth
> > >>>
> > >>>
> > >>>> -----Original message-----
> > >>>>> From:Bill Maidment <[log in to unmask]>
> > >>>>> Sent: Friday 20th January 2017 17:58
> > >>>>> To: [log in to unmask]
> > >>>>> Subject: SL7.3RC2 shutdown slow
> > >>>>>
> > >>>>> Hi
> > >>>>> I've created a new KVM guest using RC2 and no problems installing and updating from 7rolling, but rebooting is very slow.
> > >>>>> I tried doing a shutdown and notice a 1min 30sec delay shutting down Dynamic System Tuning Daemon.
> > >>>>> Is this expected behaviour on a new install?
> > >>>>>
> > >>>>> Cheers
> > >>>>> Bill Maidment
> > >>>>>
> > >>>>>
> > >>>
> > >>>
> > >>
> > >>
> >
> >
> >
start-diagnose-(1299) exited at 0s, got signals:
systemd-cgroups(1343) exited at 0.002681s, got signals:
tuned( 969) exited at 85.140172s, got signals: 9(85.140154)
gmain(1092) exited at 85.140190s, got signals: 9(85.140186)
tuned(1093) exited at 85.140209s, got signals: 9(85.140206)
tuned(1094) exited at 85.140220s, got signals: 9(85.140217)
tuned(1098) exited at 85.141821s, got signals: 9(85.140228)
systemd-cgroups(1344) exited at 85.171527s, got signals:
ip6tables-resto(1346) exited at 85.172596s, got signals:
iptables-restor(1347) exited at 85.183036s, got signals:
network(1348) exited at 85.185858s, got signals:
ebtables-restor(1349) exited at 85.193277s, got signals:
ip6tables-resto(1351) exited at 85.200834s, got signals:
ls(1352) exited at 85.207020s, got signals:
sed(1353) exited at 85.208379s, got signals:
sort(1354) exited at 85.209494s, got signals:
sed(1355) exited at 85.209691s, got signals:
network(1350) exited at 85.209949s, got signals: 17(85.209761)
iptables-restor(1356) exited at 85.214520s, got signals:
awk(1357) exited at 85.219708s, got signals:
ebtables-restor(1358) exited at 85.224399s, got signals:
awk(1359) exited at 85.228865s, got signals:
rmmod(1360) exited at 85.243352s, got signals:
rmmod(1364) exited at 85.255373s, got signals:
rmmod(1365) exited at 85.261457s, got signals:
rmmod(1366) exited at 85.268194s, got signals:
rmmod(1367) exited at 85.274284s, got signals:
rmmod(1368) exited at 85.284338s, got signals:
rmmod(1369) exited at 85.292340s, got signals:
rmmod(1370) exited at 85.300333s, got signals:
rmmod(1371) exited at 85.313280s, got signals:
rmmod(1372) exited at 85.318731s, got signals:
rmmod(1373) exited at 85.324058s, got signals:
rmmod(1374) exited at 85.329565s, got signals:
rmmod(1375) exited at 85.334896s, got signals:
rmmod(1376) exited at 85.340209s, got signals:
rmmod(1377) exited at 85.347302s, got signals:
rmmod(1378) exited at 85.354347s, got signals:
rmmod(1379) exited at 85.361276s, got signals:
rmmod(1380) exited at 85.368278s, got signals:
rmmod(1381) exited at 85.373505s, got signals:
rmmod(1382) exited at 85.380322s, got signals:
rmmod(1383) exited at 85.388306s, got signals:
rmmod(1384) exited at 85.395331s, got signals:
rmmod(1385) exited at 85.402401s, got signals:
systemctl(1361) exited at 85.408839s, got signals:
grep(1362) exited at 85.408978s, got signals:
grep(1387) exited at 85.410981s, got signals:
grep(1388) exited at 85.412222s, got signals:
rmmod(1386) exited at 85.414078s, got signals:
ip(1390) exited at 85.419940s, got signals:
grep(1391) exited at 85.421748s, got signals:
rmmod(1392) exited at 85.427285s, got signals:
rmmod(1394) exited at 85.432895s, got signals:
mountpoint(1397) exited at 85.441330s, got signals:
mountpoint(1398) exited at 85.444714s, got signals:
ifdown(1396) exited at 85.444891s, got signals: 17(85.441370) 17(85.444757)
rmmod(1395) exited at 85.452055s, got signals:
rmmod(1400) exited at 85.469953s, got signals:
nmcli(1401) exited at 85.474995s, got signals:
nmcli(1402) exited at 85.475013s, got signals: 9(85.475009)
gmain(1403) exited at 85.475025s, got signals: 9(85.475022)
gdbus(1404) exited at 85.475407s, got signals: 9(85.475031)
ifdown(1399) exited at 85.475699s, got signals: 17(85.475496)
rmmod(1405) exited at 85.483356s, got signals:
rmmod(1406) exited at 85.490304s, got signals:
firewalld( 667) exited at 85.514601s, got signals: 15(85.146434)
gmain( 894) exited at 85.517056s, got signals: 9(85.514622)
gdbus( 653) exited at 85.523235s, got signals: 9(85.523221)
polkitd( 593) exited at 85.524408s, got signals: 9(85.524400)
gmain( 652) exited at 85.524420s, got signals: 9(85.524416)
JS( 654) exited at 85.524431s, got signals: 9(85.524428)
JS( 661) exited at 85.524441s, got signals: 9(85.524437)
runaway-killer-( 663) exited at 85.525121s, got signals: 9(85.524447)
dbus-daemon( 608) exited at 85.527257s, got signals: 15(85.525933)
dbus-daemon( 630) exited at 85.529613s, got signals: 9(85.529461)
systemd-cgroups(1407) exited at 85.534816s, got signals:
mountpoint(1409) exited at 85.536449s, got signals:
mountpoint(1410) exited at 85.538120s, got signals:
ifdown-eth(1408) exited at 85.538281s, got signals: 17(85.536486) 17(85.538157)
nmcli(1412) exited at 85.555125s, got signals:
nmcli(1413) exited at 85.555460s, got signals: 9(85.555138)
ifdown-eth(1411) exited at 85.555743s, got signals: 17(85.555523)
ip(1414) exited at 85.558143s, got signals:
grep(1415) exited at 85.559350s, got signals:
mountpoint(1418) exited at 85.564037s, got signals:
mountpoint(1419) exited at 85.565664s, got signals:
ifdown-ipv6(1417) exited at 85.565824s, got signals: 17(85.564079) 17(85.565697)
nmcli(1421) exited at 85.581115s, got signals:
nmcli(1422) exited at 85.581460s, got signals: 9(85.581127)
ifdown-ipv6(1420) exited at 85.581723s, got signals: 17(85.581521)
ip(1423) exited at 85.588501s, got signals:
grep(1424) exited at 85.588619s, got signals:
sysctl(1425) exited at 85.591319s, got signals:
sysctl(1426) exited at 85.593706s, got signals:
sysctl(1427) exited at 85.596029s, got signals:
ip(1428) exited at 85.597174s, got signals:
ip(1429) exited at 85.599016s, got signals:
ip(1430) exited at 85.600126s, got signals:
ip(1431) exited at 85.601170s, got signals:
ip(1432) exited at 85.602254s, got signals:
ifdown-ipv6(1416) exited at 85.602494s, got signals: 17(85.565843) 17(85.581737) 17(85.588670) 17(85.591370) 17(85.593753) 17(85.596078) 17(85.597204) 17(85.599050) 17(85.600154) 17(85.601202) 17(85.602288)
pidof(1433) exited at 85.621141s, got signals:
ip(1434) exited at 85.623309s, got signals:
ip(1435) exited at 85.624512s, got signals:
ip(1436) exited at 85.627379s, got signals:
grep(1437) exited at 85.627493s, got signals:
mountpoint(1440) exited at 85.631826s, got signals:
mountpoint(1441) exited at 85.633450s, got signals:
ifdown-post(1439) exited at 85.633594s, got signals: 17(85.631862) 17(85.633481)
nmcli(1443) exited at 85.649062s, got signals:
nmcli(1444) exited at 85.649403s, got signals: 9(85.649078)
ifdown-post(1442) exited at 85.649670s, got signals: 17(85.649469)
ifdown-routes(1445) exited at 85.652279s, got signals:
ip(1446) exited at 85.655014s, got signals:
grep(1447) exited at 85.655112s, got signals:
ip(1448) exited at 85.656340s, got signals:
grep(1449) exited at 85.657477s, got signals:
ip(1451) exited at 85.659161s, got signals:
sed(1452) exited at 85.660385s, got signals:
ifdown-post(1450) exited at 85.660607s, got signals: 17(85.660433)
firewall-cmd(1453) exited at 85.943224s, got signals:
ifdown-post(1454) exited at 85.944193s, got signals:
ifdown-post(1438) exited at 85.944432s, got signals: 17(85.633613) 17(85.649685) 17(85.652316) 17(85.655142) 17(85.657511) 17(85.660620) 17(85.943355) 17(85.944220)
ifdown-eth(1393) exited at 85.944741s, got signals: 17(85.444911) 17(85.475716) 17(85.538303) 17(85.555760) 17(85.559392) 17(85.602529) 17(85.621166) 17(85.623346) 17(85.624555) 17(85.627526) 17(85.944472)
network(1389) exited at 85.945198s, got signals: 17(85.421795) 17(85.944784)
mountpoint(1457) exited at 85.951232s, got signals:
mountpoint(1458) exited at 85.952871s, got signals:
ifdown(1456) exited at 85.953025s, got signals: 17(85.951274) 17(85.952908)
ifdown(1460) exited at 85.960093s, got signals:
sed(1461) exited at 85.961392s, got signals:
ifdown(1459) exited at 85.961616s, got signals: 17(85.961446)
nmcli(1463) exited at 85.971529s, got signals:
nmcli(1464) exited at 85.971914s, got signals: 9(85.971541)
ifdown(1462) exited at 85.972144s, got signals: 17(85.971983)
mountpoint(1466) exited at 85.976110s, got signals:
mountpoint(1467) exited at 85.977749s, got signals:
ifdown-eth(1465) exited at 85.977909s, got signals: 17(85.976147) 17(85.977786)
ifdown-eth(1469) exited at 85.985015s, got signals:
sed(1470) exited at 85.986301s, got signals:
ifdown-eth(1468) exited at 85.986508s, got signals: 17(85.986357)
nmcli(1472) exited at 85.995378s, got signals:
nmcli(1473) exited at 85.995737s, got signals: 9(85.995390)
ifdown-eth(1471) exited at 85.995952s, got signals: 17(85.995800)
ip(1474) exited at 85.997660s, got signals:
grep(1475) exited at 85.998822s, got signals:
mountpoint(1478) exited at 86.003086s, got signals:
mountpoint(1479) exited at 86.004716s, got signals:
ifdown-ipv6(1477) exited at 86.004860s, got signals: 17(86.003128) 17(86.004756)
ifdown-ipv6(1481) exited at 86.011666s, got signals:
sed(1482) exited at 86.012900s, got signals:
ifdown-ipv6(1480) exited at 86.013112s, got signals: 17(86.012957)
nmcli(1484) exited at 86.022053s, got signals:
nmcli(1485) exited at 86.022391s, got signals: 9(86.022074)
ifdown-ipv6(1483) exited at 86.022617s, got signals: 17(86.022450)
ip(1486) exited at 86.029135s, got signals:
grep(1487) exited at 86.029242s, got signals:
sysctl(1488) exited at 86.031755s, got signals:
sysctl(1489) exited at 86.034159s, got signals:
sysctl(1490) exited at 86.036477s, got signals:
ip(1491) exited at 86.037630s, got signals:
ip(1492) exited at 86.039245s, got signals:
ip(1493) exited at 86.040352s, got signals:
ifdown-ipv6(1476) exited at 86.040608s, got signals: 17(86.004877) 17(86.013124) 17(86.022630) 17(86.029274) 17(86.031806) 17(86.034208) 17(86.036525) 17(86.037687) 17(86.039279) 17(86.040386)
pidof(1494) exited at 86.044941s, got signals:
ip(1495) exited at 86.046275s, got signals:
ip(1496) exited at 86.047425s, got signals:
ip(1497) exited at 86.050122s, got signals:
grep(1498) exited at 86.050238s, got signals:
mountpoint(1501) exited at 86.054040s, got signals:
mountpoint(1502) exited at 86.055601s, got signals:
ifdown-post(1500) exited at 86.055782s, got signals: 17(86.054076) 17(86.055657)
ifdown-post(1504) exited at 86.062627s, got signals:
sed(1505) exited at 86.063872s, got signals:
ifdown-post(1503) exited at 86.064075s, got signals: 17(86.063923)
nmcli(1507) exited at 86.073178s, got signals:
nmcli(1508) exited at 86.073507s, got signals: 9(86.073190)
ifdown-post(1506) exited at 86.073754s, got signals: 17(86.073578)
ifdown-routes(1509) exited at 86.076022s, got signals:
ip(1510) exited at 86.077580s, got signals:
grep(1511) exited at 86.078796s, got signals:
ip(1512) exited at 86.080065s, got signals:
grep(1513) exited at 86.081144s, got signals:
ifdown-post(1514) exited at 86.082056s, got signals:
ifdown-post(1499) exited at 86.082301s, got signals: 17(86.055803) 17(86.064086) 17(86.073769) 17(86.076057) 17(86.078835) 17(86.081184) 17(86.082110)
ifdown-eth(1455) exited at 86.082573s, got signals: 17(85.953044) 17(85.961629) 17(85.972157) 17(85.977926) 17(85.986520) 17(85.995962) 17(85.998863) 17(86.040669) 17(86.044964) 17(86.046310) 17(86.047457) 17(86.050268) 17(86.082349)
sysctl(1515) exited at 86.085605s, got signals:
mountpoint(1518) exited at 86.089428s, got signals:
mountpoint(1519) exited at 86.091125s, got signals:
init.ipv6-globa(1517) exited at 86.091287s, got signals: 17(86.089470) 17(86.091164)
sysctl(1520) exited at 86.103461s, got signals:
sysctl(1521) exited at 86.105774s, got signals:
sysctl(1522) exited at 86.108029s, got signals:
sysctl(1523) exited at 86.110346s, got signals:
sysctl(1524) exited at 86.112654s, got signals:
sysctl(1525) exited at 86.114932s, got signals:
sysctl(1526) exited at 86.117279s, got signals:
sysctl(1527) exited at 86.119593s, got signals:
sysctl(1528) exited at 86.121888s, got signals:
sysctl(1529) exited at 86.124242s, got signals:
sysctl(1530) exited at 86.126527s, got signals:
sysctl(1531) exited at 86.128851s, got signals:
ip(1532) exited at 86.130599s, got signals:
awk(1533) exited at 86.131859s, got signals:
init.ipv6-globa(1534) exited at 86.132046s, got signals:
init.ipv6-globa(1516) exited at 86.132396s, got signals: 17(86.091308) 17(86.103511) 17(86.105822) 17(86.108077) 17(86.110396) 17(86.112702) 17(86.114980) 17(86.117328) 17(86.119635) 17(86.121930) 17(86.124300) 17(86.126589) 17(86.128900) 17(86.132083)
rm(1535) exited at 86.133829s, got signals:
network(1345) exited at 86.134129s, got signals: 17(85.185881) 17(85.209961) 17(85.219739) 17(85.228894) 17(85.409035) 17(85.411000) 17(85.412240) 17(85.947157) 17(86.082614) 17(86.085692) 17(86.132428) 17(86.133860)
systemd-cgroups(1537) exited at 86.150609s, got signals:
systemd-random-(1536) exited at 86.153664s, got signals:
audit_send_repl(1538) exited at 86.154967s, got signals:
systemd-cgroups(1539) exited at 86.155807s, got signals:
auditd( 587) exited at 86.165145s, got signals:
auditd( 572) exited at 86.166271s, got signals: 15(86.138891)
umount(1543) exited at 86.182006s, got signals:
systemd-cgroups(1540) exited at 86.187308s, got signals:
umount(1542) exited at 86.193041s, got signals:
systemd-cgroups(1544) exited at 86.195477s, got signals:
xfsaild/vda1( 545) exited at 86.371222s, got signals:
xfs-eofblocks/v( 544) exited at 86.373343s, got signals:
xfs-log/vda1( 543) exited at 86.373926s, got signals:
xfs-reclaim/vda( 542) exited at 86.374472s, got signals:
xfs-cil/vda1( 541) exited at 86.375090s, got signals:
xfs-data/vda1( 539) exited at 86.375342s, got signals:
xfs-conv/vda1( 540) exited at 86.375639s, got signals:
xfs-buf/vda1( 538) exited at 86.375974s, got signals:
umount(1541) exited at 86.384167s, got signals:
systemctl(1547) exited at 87.199818s, got signals:
systemd-cgroups(1548) exited at 87.328650s, got signals:
systemd-udevd(1363) exited at 88.438277s, got signals: 19(88.166685)
lvm(1546) exited at 88.450533s, got signals: 19(88.167202) 15(88.416993)
lvmetad(1549) exited at 88.452329s, got signals:
lvmetad( 480) exited at 88.550239s, got signals: 19(88.166181) 15(88.367595)
systemd-udevd( 491) exited at 88.572941s, got signals: 19(88.166371)
systemd-journal( 460) exited at 88.594365s, got signals: 19(88.167293)
kdmflush( 366) exited at 89.332885s, got signals:
bioset( 367) exited at 89.332920s, got signals:
mount(1554) exited at 89.457240s, got signals:
mdadm(1553) exited at 89.466173s, got signals:
mdadm.shutdown(1551) exited at 89.466814s, got signals: 17(89.466676)
|
