[ClusterLabs] Antw: [EXT] Re: Some unexpected DLM messages; OCFS2 related? "send_repeat_remove dir" / "send_repeat_remove dir"

Ulrich Windl Ulrich.Windl at rz.uni-regensburg.de
Mon Oct 11 02:55:22 EDT 2021 

>>> Gang He <ghe at suse.com> schrieb am 09.10.2021 um 07:54 in Nachricht
<3aaa716d-07a9-29f9-4504-9d5d339a6714 at suse.com>:
> Hello Ulrich,
> 
> See my comments inline.
> 
> 
> On 2021/10/8 16:38, Ulrich Windl wrote:
>> Hi!
>> 
>> I just noticed these two messages on two nodes of a 3-node cluster:
>> Oct 08 10:00:14 h18 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: 
> send_repeat_remove dir 119 O000000000000000009d83500000000
>> Oct 08 10:00:14 h19 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: 
> receive_remove from 118 not found O000000000000000009d83500000000
> These two line messages were printed fs/dlm kernel module when it 
> handled dlm lock resource related things.
> For "send_repeat_remove dir", it does not refer to ocfs2 directory, is 
> related to dlm implementation details.
> 
> So far, did you encounter any ocfs2 file system level problem? e.g. file 
> system hang, etc.

Hi!

Not that I knew. But it looks as if something went wrong.
Also see my comment below.

> 
> 
> Thanks
> Gang
> 
>> 
>> Due to "genuine configuration"TM node id 118 corresponds to node h18, while 
> 119 corresponds to (you guessed it!) node h19.
>> 
>> journalctl colors these messages in red, so I guess they are somewhat 
> unexpected.
>> 
>> My guess is that the messages are related to OCFS2 reflink snapshots that 
> are created every hour (and may take 15 Seconds).
>> The kernel is 5.3.18-24.83-default (SLES15 SP2) on all nodes, and we 
> actually had a lockup on OCFS2 snapshots with some older kernels.
>> So I wonder whether those messages may still be an indication of some 
> problem.
>> 
>> My snapshots do not create any directories ("dir"), BTW. But the nodes 
> create/rename/remove different files in the same directory.
>> 
>> Actually I have snapshots with these date stamps:
>> Change: 2021-10-08 10:00:10.275375897 +0200
>> Change: 2021-10-08 10:00:15.371632277 +0200
>> Change: 2021-10-08 10:00:15.371632277 +0200
>> Change: 2021-10-08 10:00:15.371632277 +0200
>> Change: 2021-10-08 10:00:15.371632277 +0200
>> Change: 2021-10-08 10:00:15.371632277 +0200

What surprises me is that five snapshots seem to have been created at the very same nanosecond.
As the clock resolution in the kernel is definitely quite high, and snapshot creation is expected to need more than 1 nanosecond, I'm surprised, specifically if those were created from possiblky different nodes.

>> Change: 2021-10-08 10:00:15.443455304 +0200
>> Change: 2021-10-08 10:00:15.938216584 +0200
>> Change: 2021-10-08 10:00:15.974216964 +0200
>> Change: 2021-10-08 10:00:16.183466675 +0200
>> Change: 2021-10-08 10:00:16.223467289 +0200
>> Change: 2021-10-08 10:00:16.251467719 +0200
>> Change: 2021-10-08 10:00:17.375484990 +0200
>> Change: 2021-10-08 10:00:18.187497465 +0200
>> Change: 2021-10-08 10:00:18.843647739 +0200

When I just checked the dates of _all_ snapshots, I also found a few (stat snapshots/* |grep 'Change.* ' |sort -n |uniq -c):
      1 Change: 2021-01-14 15:24:27.545104741 +0100
      1 Change: 2021-01-14 16:00:01.588092517 +0100
      1 Change: 2021-01-14 16:00:01.779160728 +0100
      1 Change: 2021-01-14 16:00:02.235163734 +0100
      1 Change: 2021-01-28 11:00:01.680863347 +0100
      1 Change: 2021-02-17 09:00:01.351288565 +0100
      1 Change: 2021-02-18 10:00:02.240502525 +0100
      1 Change: 2021-02-18 15:00:02.240842416 +0100
      1 Change: 2021-02-23 13:00:01.783326965 +0100
      1 Change: 2021-02-24 12:00:02.323505005 +0100
      1 Change: 2021-02-25 10:00:02.059403291 +0100
      1 Change: 2021-02-25 16:00:01.373293566 +0100
      1 Change: 2021-03-01 11:00:02.286537993 +0100
      1 Change: 2021-03-03 15:00:01.828856949 +0100
      1 Change: 2021-08-06 11:00:02.967838173 +0200
      1 Change: 2021-08-11 09:36:42.053718646 +0200
      2 Change: 2021-10-01 02:00:01.634857518 +0200
      1 Change: 2021-10-01 02:00:05.698926423 +0200
      1 Change: 2021-10-01 02:00:10.508967011 +0200
      1 Change: 2021-10-01 02:00:10.527008277 +0200
      1 Change: 2021-10-01 02:00:12.779046458 +0200
      1 Change: 2021-10-01 02:00:12.789109330 +0200
      1 Change: 2021-10-01 02:00:12.797109829 +0200
      1 Change: 2021-10-01 02:00:12.805110329 +0200
      1 Change: 2021-10-01 02:00:12.819020811 +0200
      1 Change: 2021-10-01 02:00:12.827020850 +0200
      1 Change: 2021-10-01 02:00:12.835020890 +0200
      1 Change: 2021-10-01 02:00:12.885115323 +0200
      1 Change: 2021-10-01 02:00:12.899021204 +0200
      1 Change: 2021-10-01 02:00:12.903048562 +0200
      1 Change: 2021-10-01 02:00:12.911048698 +0200
      1 Change: 2021-10-01 02:00:12.919048833 +0200
      1 Change: 2021-10-01 02:00:12.923048900 +0200
      1 Change: 2021-10-01 02:00:12.931049036 +0200
      1 Change: 2021-10-01 02:00:12.935049105 +0200
      1 Change: 2021-10-01 02:00:12.943049240 +0200
      1 Change: 2021-10-01 02:00:12.955021478 +0200
      1 Change: 2021-10-01 02:00:12.959021498 +0200
      1 Change: 2021-10-01 02:00:12.967021537 +0200
      1 Change: 2021-10-01 02:00:12.975021577 +0200
      1 Change: 2021-10-01 02:00:12.983021616 +0200
      1 Change: 2021-10-01 02:00:12.987021636 +0200
      1 Change: 2021-10-01 02:00:12.991050054 +0200
      1 Change: 2021-10-01 02:00:13.003050256 +0200
      1 Change: 2021-10-01 02:00:14.139027286 +0200
      1 Change: 2021-10-01 02:00:14.143027306 +0200
      1 Change: 2021-10-01 02:00:14.407074060 +0200
      1 Change: 2021-10-01 02:00:16.511109737 +0200
      1 Change: 2021-10-01 02:00:16.515109803 +0200
      1 Change: 2021-10-01 02:00:16.881364753 +0200
      1 Change: 2021-10-01 02:00:16.885365002 +0200
      2 Change: 2021-10-01 02:00:17.635044433 +0200
      1 Change: 2021-10-01 02:00:20.789608685 +0200
      1 Change: 2021-10-01 02:00:20.791182299 +0200
      1 Change: 2021-10-01 02:00:21.623063991 +0200
      1 Change: 2021-10-01 02:00:21.655064148 +0200
      1 Change: 2021-10-01 02:00:22.331208405 +0200
      1 Change: 2021-10-01 02:00:22.371209083 +0200
      1 Change: 2021-10-01 02:00:22.909741014 +0200
      1 Change: 2021-10-01 02:00:23.579073585 +0200
      1 Change: 2021-10-01 02:00:27.755300363 +0200
      1 Change: 2021-10-01 02:00:29.579103009 +0200
      1 Change: 2021-10-08 02:00:02.156693789 +0200
      1 Change: 2021-10-08 02:00:02.184694077 +0200
      1 Change: 2021-10-08 02:00:07.084744567 +0200
      1 Change: 2021-10-08 02:00:08.198233758 +0200
      1 Change: 2021-10-08 02:00:08.206233880 +0200
      1 Change: 2021-10-08 02:00:09.580770288 +0200
      1 Change: 2021-10-08 02:00:10.090262675 +0200
      1 Change: 2021-10-08 02:00:12.776141558 +0200
      1 Change: 2021-10-08 02:00:12.788141611 +0200
      1 Change: 2021-10-08 02:00:12.798304063 +0200
      1 Change: 2021-10-08 02:00:12.802304125 +0200
      1 Change: 2021-10-08 02:00:12.808803548 +0200
      1 Change: 2021-10-08 02:00:12.816803631 +0200
      1 Change: 2021-10-08 02:00:12.824141768 +0200
      1 Change: 2021-10-08 02:00:12.852141892 +0200
      1 Change: 2021-10-08 02:00:14.138324543 +0200
      1 Change: 2021-10-08 02:00:14.796824033 +0200
      1 Change: 2021-10-08 02:00:14.800824074 +0200
      1 Change: 2021-10-08 02:00:14.826335061 +0200
      2 Change: 2021-10-08 02:00:14.874335793 +0200
      1 Change: 2021-10-08 02:00:15.610347043 +0200
      1 Change: 2021-10-08 02:00:16.666363181 +0200
      1 Change: 2021-10-08 02:00:18.668167566 +0200
      1 Change: 2021-10-08 02:00:19.828875881 +0200
      1 Change: 2021-10-08 02:00:20.098415637 +0200
      1 Change: 2021-10-08 02:00:20.204879753 +0200
      1 Change: 2021-10-08 02:00:23.692189741 +0200
      1 Change: 2021-10-08 02:00:24.284192356 +0200
      1 Change: 2021-10-08 02:00:32.832230086 +0200
      1 Change: 2021-10-08 02:00:33.040231004 +0200
      1 Change: 2021-10-08 02:00:40.060261992 +0200
      1 Change: 2021-10-11 02:00:04.917690158 +0200
      1 Change: 2021-10-11 02:00:11.689792390 +0200
      1 Change: 2021-10-11 02:00:12.632739107 +0200
      1 Change: 2021-10-11 02:00:12.649806884 +0200
      1 Change: 2021-10-11 02:00:12.656739210 +0200
      1 Change: 2021-10-11 02:00:12.668739261 +0200
      1 Change: 2021-10-11 02:00:12.681807367 +0200
      1 Change: 2021-10-11 02:00:12.685807428 +0200
      1 Change: 2021-10-11 02:00:12.692175364 +0200
      1 Change: 2021-10-11 02:00:12.704739416 +0200
      1 Change: 2021-10-11 02:00:12.724739502 +0200
      1 Change: 2021-10-11 02:00:12.733808155 +0200
      1 Change: 2021-10-11 02:00:12.741808275 +0200
      1 Change: 2021-10-11 02:00:12.748739605 +0200
      1 Change: 2021-10-11 02:00:12.768176226 +0200
      1 Change: 2021-10-11 02:00:12.776176315 +0200
      1 Change: 2021-10-11 02:00:12.781808879 +0200
      1 Change: 2021-10-11 02:00:12.789808999 +0200
      1 Change: 2021-10-11 02:00:12.796739810 +0200
      1 Change: 2021-10-11 02:00:12.816739896 +0200
      1 Change: 2021-10-11 02:00:12.821809483 +0200
      1 Change: 2021-10-11 02:00:12.832176949 +0200
      1 Change: 2021-10-11 02:00:12.837809724 +0200
      1 Change: 2021-10-11 02:00:12.845809844 +0200
      1 Change: 2021-10-11 02:00:12.852177176 +0200
      1 Change: 2021-10-11 02:00:12.860177266 +0200
      1 Change: 2021-10-11 02:00:13.200181114 +0200
      1 Change: 2021-10-11 02:00:13.204181160 +0200
      1 Change: 2021-10-11 02:00:13.205815278 +0200
      2 Change: 2021-10-11 02:00:13.224181389 +0200
      1 Change: 2021-10-11 02:00:13.265816184 +0200
      1 Change: 2021-10-11 02:00:13.301816729 +0200
      1 Change: 2021-10-11 02:00:14.049828028 +0200
      1 Change: 2021-10-11 02:00:14.649837179 +0200
      1 Change: 2021-10-11 02:00:15.084749635 +0200
      1 Change: 2021-10-11 02:00:15.088202494 +0200
      1 Change: 2021-10-11 02:00:15.757854076 +0200
      1 Change: 2021-10-11 02:00:17.000224148 +0200
      1 Change: 2021-10-11 02:00:17.000757861 +0200
      1 Change: 2021-10-11 02:00:18.544241632 +0200
      1 Change: 2021-10-11 02:00:19.948257531 +0200
      1 Change: 2021-10-11 02:00:20.384262468 +0200
      1 Change: 2021-10-11 02:00:21.100775464 +0200
      1 Change: 2021-10-11 02:00:23.540785940 +0200
      1 Change: 2021-10-11 02:00:25.564794628 +0200
      1 Change: 2021-10-11 02:00:28.040805260 +0200
      1 Change: 2021-10-11 02:00:36.256840533 +0200
      1 Change: 2021-10-11 08:00:06.491334973 +0200
      1 Change: 2021-10-11 08:00:06.611335504 +0200
      1 Change: 2021-10-11 08:00:07.810331171 +0200
      1 Change: 2021-10-11 08:00:07.827340888 +0200
      1 Change: 2021-10-11 08:00:07.939341384 +0200
      1 Change: 2021-10-11 08:00:07.990333921 +0200
      1 Change: 2021-10-11 08:00:08.002334105 +0200
      1 Change: 2021-10-11 08:00:08.006334168 +0200
      1 Change: 2021-10-11 08:00:08.034334596 +0200
      1 Change: 2021-10-11 08:00:08.040836920 +0200
      1 Change: 2021-10-11 08:00:08.052837060 +0200
      1 Change: 2021-10-11 08:00:08.056837108 +0200
      1 Change: 2021-10-11 08:00:08.064837201 +0200
      1 Change: 2021-10-11 08:00:08.352840595 +0200
      1 Change: 2021-10-11 08:00:08.711344803 +0200
      1 Change: 2021-10-11 08:00:08.952847666 +0200
      1 Change: 2021-10-11 08:00:09.406355571 +0200
      1 Change: 2021-10-11 08:00:10.690375194 +0200
      1 Change: 2021-10-11 08:00:10.775353941 +0200
      1 Change: 2021-10-11 08:00:10.918378679 +0200
      1 Change: 2021-10-11 08:00:10.920870862 +0200
      1 Change: 2021-10-11 08:00:10.946379106 +0200
      2 Change: 2021-10-11 08:00:10.988871662 +0200
      2 Change: 2021-10-11 08:00:11.371356580 +0200
      1 Change: 2021-10-11 08:00:11.428876849 +0200
      1 Change: 2021-10-11 08:00:11.502387605 +0200
      1 Change: 2021-10-11 08:00:11.538388155 +0200
      1 Change: 2021-10-11 08:00:11.578388767 +0200
      1 Change: 2021-10-11 08:00:13.167364533 +0200
      1 Change: 2021-10-11 08:00:17.303382845 +0200

I checked on case (that last one): Both snapshots were created on the same node, but for different files (from different processes).
Also true for the second to last (different node). I did not check the rest.

Regards,
Ulrich

More information about the Users mailing list