From mboxrd@z Thu Jan 1 00:00:00 1970 From: Vyacheslav Dubeyko Subject: Re: very large mount time after unxepected power down Date: Tue, 27 Nov 2012 11:58:30 +0400 Message-ID: <1354003110.2037.14.camel@slavad-ubuntu> References: <1351604965.2069.13.camel@slavad-ubuntu> <1351608774.2026.6.camel@slavad-ubuntu> <1351664002.2105.3.camel@slavad-ubuntu> <1352961172.2076.10.camel@slavad-ubuntu> <1353047197.2029.5.camel@slavad-ubuntu> <1353048835.2029.17.camel@slavad-ubuntu> <1353073969.9135.7.camel@slavad-ubuntu> <782558C7-081D-4466-8780-51886E209A62@dubeyko.com> <1354000375.2037.7.camel@slavad-ubuntu> Mime-Version: 1.0 Content-Transfer-Encoding: QUOTED-PRINTABLE Return-path: DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=dubeyko.com; s=default; h=Mime-Version:Content-Transfer-Encoding:Content-Type:References:In-Reply-To:Date:Cc:To:From:Subject:Message-ID; bh=CyGJO/WXOuDoEZDT0xTJOlJU2uglEuw7q96Jo6jHFoc=; b=f6v1qP3ga7PoybQ7VI8exeHK8tKSgJKJSIMJ4DTvFq8YIWBjZQ0r0R17cATa/B/i4fHP4z+k9SNC+Pawh81luJ6OzehoKCRFKeL3M3PanQHlVqHt0XmcPcDiuOgBp5gh; In-Reply-To: Sender: linux-nilfs-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org List-ID: Content-Type: text/plain; charset="utf-8" To: =?UTF-8?Q?=D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9_?= =?UTF-8?Q?=D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE?= =?UTF-8?Q?=D0=B2?= Cc: linux-nilfs-u79uwXL29TY76Z2rM5mHXA@public.gmane.org On Tue, 2012-11-27 at 10:47 +0300, =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9= =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2 wro= te: > Hi, >=20 > Yes, I it's not a full output, it's an output for abut 2 minutes. > I can get a full one, but after that the partition apparently will be > checked and it' will be hard to reproduce. > I also can split md device, so that there will be another attempt, sh= ould I? If you get enough disk space then it is possible to get full volume image. And, as a result, to get issue reproducible volume state by mean= s of mount volume replica as loop device anytime. Could you do it? I think that we need to get whole output of mount operation anyway for the issue analysis. With the best regards, Vyacheslav Dubeyko. > -------------------------------------------------- > =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2 =D0= =A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9 =D0=92=D0=B0=D1=81=D0=B8=D0=BB=D1=8C=D0= =B5=D0=B2=D0=B8=D1=87 >=20 >=20 > 2012/11/27 Vyacheslav Dubeyko : > > Hi, > > > > On Mon, 2012-11-26 at 22:17 +0300, =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0= =B9 =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2 = wrote: > >> Hi, > >> > >> Unfortunately, the only output I saw is: > >> Nov 26 15:54:00 router kernel: [ 5808.068533] NILFS warning: mount= ing > >> unchecked fs > >> Nov 26 15:54:00 router kernel: [ 5808.068546] NILFS: nilfs_search_= super_root > >> Nov 26 15:54:00 router kernel: [ 5808.068552] NILFS: pseg_start > >> 115603456, seg_seq 4347757 > >> Nov 26 15:54:00 router kernel: [ 5808.068558] NILFS: cno 1252241, = segnum 56447 > >> > > > > Sorry, the patch is working. The output about searching super root = is > > the result of debug output. But I expected more information in this > > output. Did you break mount operation before ending? > > > > As I understand, you have output not for whole mount operation. Am = I > > correct? Could you share whole debug output from the mount beginnin= g to > > the end? > > > > Or do you share all available output that you had during so long mo= unt > > operation? > > > >> I suppose the last three lines are due to the patch. > >> > >> Dynamic debug was on: > >> router dynamic_debug # cat control | grep nilfs > >> fs/nilfs2/recovery.c:851 [nilfs2]nilfs_search_super_root =3Dp "NIL= =46S: > >> cno %lld, segnum %lld\012" > >> fs/nilfs2/recovery.c:850 [nilfs2]nilfs_search_super_root =3Dp "NIL= =46S: > >> pseg_start %lld, seg_seq %lld\012" > >> fs/nilfs2/recovery.c:849 [nilfs2]nilfs_search_super_root =3Dp "NIL= =46S: > >> nilfs_search_super_root\012" > >> fs/nilfs2/recovery.c:766 [nilfs2]nilfs_salvage_orphan_logs =3Dp "N= ILFS: > >> nilfs_salvage_orphan_logs\012" > >> fs/nilfs2/recovery.c:614 [nilfs2]nilfs_do_roll_forward =3Dp "NILFS= : > >> seg_start %lld, seg_end %lld\012" > >> fs/nilfs2/recovery.c:613 [nilfs2]nilfs_do_roll_forward =3Dp "NILFS= : > >> segnum %lld\012" > >> fs/nilfs2/recovery.c:612 [nilfs2]nilfs_do_roll_forward =3Dp "NILFS= : > >> pseg_start %lld, seg_seq %lld\012" > >> fs/nilfs2/recovery.c:611 [nilfs2]nilfs_do_roll_forward =3Dp "NILFS= : > >> nilfs_do_roll_forward\012" > >> fs/nilfs2/recovery.c:442 [nilfs2]nilfs_prepare_segment_for_recover= y =3Dp > >> "NILFS: ri_segnum %lld, ri_nextnum %lld\012" > >> fs/nilfs2/recovery.c:440 [nilfs2]nilfs_prepare_segment_for_recover= y =3Dp > >> "NILFS: ns_segnum %lld, ns_nextnum %lld\012" > >> fs/nilfs2/recovery.c:438 [nilfs2]nilfs_prepare_segment_for_recover= y =3Dp > >> "NILFS: nilfs_prepare_segment_for_recovery\012" > >> fs/nilfs2/recovery.c:719 [nilfs2]nilfs_finish_roll_forward =3Dp "N= ILFS: > >> nilfs_finish_roll_forward\012" > > > > This is simply list of known debug messages format. > > > > With the best regards, > > Vyacheslav Dubeyko. > > > >> -------------------------------------------------- > >> =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2= =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9 =D0=92=D0=B0=D1=81=D0=B8=D0=BB=D1= =8C=D0=B5=D0=B2=D0=B8=D1=87 > >> > >> > >> 2012/11/27 Vyacheslav Dubeyko : > >> > Hi, > >> > > >> > On Nov 26, 2012, at 7:19 PM, =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9= =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2 wro= te: > >> > > >> >> The bug finally appeared again. Here are the trace log and kern= el log. > >> >> I've hard rebooted machine so FS is in unchecked state for now = and it > >> >> is possible to make some other tests. > >> >> I'll manage to do without this partition for a day may be two. > >> >> > >> > > >> > Thank you for logs. But what about my patch with debug output? T= he output of the patch can be very helpful for the issue analysis. It n= eeds to understand what segments are processed during mount. Could you = share debug output of my patch? > >> > > >> > With the best regards, > >> > Vyacheslav Dubeyko. > >> > > >> >> > >> >> -------------------------------------------------- > >> >> =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0= =B2 =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9 =D0=92=D0=B0=D1=81=D0=B8=D0=BB= =D1=8C=D0=B5=D0=B2=D0=B8=D1=87 > >> >> > >> >> > >> >> 2012/11/16 =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9 =D0=90=D0=BB=D0= =B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0=B2 = : > >> >>> Ok, thanks. I'll try to apply it. I've also turned on function= graph > >> >>> tracing, may be the graph for init_nilfs function will help. > >> >>> -------------------------------------------------- > >> >>> =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0= =B2 =D0=A1=D0=B5=D1=80=D0=B3=D0=B5=D0=B9 =D0=92=D0=B0=D1=81=D0=B8=D0=BB= =D1=8C=D0=B5=D0=B2=D0=B8=D1=87 > >> >>> > >> >>> > >> >>> 2012/11/16 Vyacheslav Dubeyko : > >> >>>> On Fri, 2012-11-16 at 10:11 +0300, =D0=A1=D0=B5=D1=80=D0=B3=D0= =B5=D0=B9 =D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B0=D0=BD=D0=B4=D1=80=D0=BE=D0= =B2 wrote: > >> >>>>> dmesg: > >> >>>>> [53994.254432] NILFS warning: mounting unchecked fs > >> >>>>> [56686.968229] NILFS: recovery complete. > >> >>>>> [56686.969316] segctord starting. Construction interval =3D = 5 seconds, > >> >>>>> CP frequency < 30 seconds > >> >>>>> > >> >>>>> messages: > >> >>>>> Nov 15 10:57:06 router kernel: [53994.254432] NILFS warning:= mounting > >> >>>>> unchecked fs > >> >>>>> Nov 15 11:42:02 router kernel: [56686.968229] NILFS: recover= y complete. > >> >>>>> Nov 15 11:42:02 router kernel: [56686.969316] segctord start= ing. > >> >>>>> Construction interval =3D 5 seconds, CP frequency < 30 secon= ds > >> >>>>> > >> >>>>> May be there is some kernel config option to get more debug = output? > >> >>>>> > >> >>>> > >> >>>> I prepared small patch (please, find in attachment). This pat= ch simply > >> >>>> adds several debug messages into recovery module. I suggest t= o apply the > >> >>>> patch on your NILFS2 driver and try to mount again in the iss= ue > >> >>>> environment. I hope that these debug messages can give more i= nformation > >> >>>> about issue on your side. > >> >>>> > >> >>>> The patch uses pr_debug() call. Please, see > >> >>>> Documentation/dynamic-debug-howto.txt for more details. > >> >>>> > >> >>>> To be honest, I don't test the patch yet. So, if you will hav= e any > >> >>>> troubles, please, e-mail to me. > >> >>>> > >> >>>> With the best regards, > >> >>>> Vyacheslav Dubeyko. > >> >>>> > >> >>>>> As for fsck, I have not found it in git public repo, so wher= e can I > >> >>>>> get the latest version? > >> >>>>> -------------------------------------------------- > >> >>>> > >> >> > >> > > > > > > -- > To unsubscribe from this list: send the line "unsubscribe linux-nilfs= " in > the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org > More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe linux-nilfs" = in the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org More majordomo info at http://vger.kernel.org/majordomo-info.html