Project

General

Profile

Bug #38679

mds: behind on trimming and "[dentry] was purgeable but no longer is!"

Added by Patrick Donnelly 7 months ago. Updated 3 days ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
-
Target version:
Start date:
Due date:
% Done:

0%

Source:
Q/A
Tags:
Backport:
nautilus,mimic,luminous
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS
Labels (FS):
multimds
Pull request ID:
Crash signature:

Description

2019-03-07T22:22:01.852 INFO:teuthology.orchestra.run.smithi179:> mkdir -p -- /home/ubuntu/cephtest/mnt.1/client.1/tmp && cd -- /home/ubuntu/cephtest/mnt.1/client.1/tmp && CEPH_CLI_TEST_DUP_COMMAND=1 CEPH_REF=4a8e27e6efdaad211a513d7fcdf7736bf8cebb71 TESTDIR="/home/ubuntu/cephtest" CEPH_ARGS="--cluster ceph" CEPH_ID="1" PATH=$PATH:/usr/sbin CEPH_BASE=/home/ubuntu/cephtest/clone.client.1 CEPH_ROOT=/home/ubuntu/cephtest/clone.client.1 adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 3h /home/ubuntu/cephtest/clone.client.1/qa/workunits/fs/misc/dirfrag.sh
2019-03-07T22:22:01.961 INFO:tasks.workunit.client.1.smithi179.stdout:creating folder hierarchy
2019-03-07T22:22:01.962 INFO:tasks.workunit.client.0.smithi179.stdout:creating folder hierarchy
2019-03-07T22:22:09.948 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:22:09.948 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:22:09.952 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:22:09.952 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:22:09.956 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:22:09.956 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:22:40.105 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:22:40.106 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:22:40.110 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:22:40.110 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:22:40.114 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:22:40.115 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:10.424 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:23:10.424 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:10.428 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:23:10.428 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:10.431 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:23:10.432 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:29.459 INFO:tasks.workunit.client.0.smithi179.stdout:created hierarchy, now cleaning up
2019-03-07T22:23:45.038 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:23:45.038 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:45.042 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:23:45.042 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:23:45.047 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:23:45.047 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:06.940 INFO:tasks.workunit.client.1.smithi179.stdout:created hierarchy, now cleaning up
2019-03-07T22:24:20.029 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:24:20.029 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:20.055 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:24:20.055 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:20.074 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:24:20.074 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:57.842 INFO:teuthology.orchestra.run.smithi167:Running:
2019-03-07T22:24:57.843 INFO:teuthology.orchestra.run.smithi167:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:57.875 INFO:teuthology.orchestra.run.smithi170:Running:
2019-03-07T22:24:57.876 INFO:teuthology.orchestra.run.smithi170:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:57.880 INFO:teuthology.orchestra.run.smithi179:Running:
2019-03-07T22:24:57.880 INFO:teuthology.orchestra.run.smithi179:> sudo logrotate /etc/logrotate.d/ceph-test.conf
2019-03-07T22:24:59.192 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:24:59.198 7efd6f00b700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 8637) UID: 0
2019-03-07T22:24:59.192 INFO:tasks.ceph.mds.c.smithi167.stderr:2019-03-07 22:24:59.199 7ffbe027b700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 8637) UID: 0
2019-03-07T22:25:01.146 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009bc2 [2,head] auth (dversion lock) v=4642 ino=0x10000009bc2 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c1c4fc0] was purgeable but no longer is!
2019-03-07T22:25:01.147 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009af3 [2,head] auth (dversion lock) v=4644 ino=0x10000009af3 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5db29dc0] was purgeable but no longer is!
2019-03-07T22:25:01.147 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a640 [2,head] auth (dversion lock) v=4646 ino=0x1000000a640 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5dc79500] was purgeable but no longer is!
2019-03-07T22:25:01.147 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a45f [2,head] auth (dversion lock) v=4648 ino=0x1000000a45f state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5925ba40] was purgeable but no longer is!
2019-03-07T22:25:01.147 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a394 [2,head] auth (dversion lock) v=4650 ino=0x1000000a394 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b2700] was purgeable but no longer is!
2019-03-07T22:25:01.147 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a49b [2,head] auth (dversion lock) v=4652 ino=0x1000000a49b state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5df17dc0] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a201 [2,head] auth (dversion lock) v=4654 ino=0x1000000a201 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5dc79880] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a4e4 [2,head] auth (dversion lock) v=4656 ino=0x1000000a4e4 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5aa4dc00] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a3f1 [2,head] auth (dversion lock) v=4658 ino=0x1000000a3f1 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5df16fc0] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a3fe [2,head] auth (dversion lock) v=4660 ino=0x1000000a3fe state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b5340] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a081 [2,head] auth (dversion lock) v=4662 ino=0x1000000a081 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5da16000] was purgeable but no longer is!
2019-03-07T22:25:01.148 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a14e [2,head] auth (dversion lock) v=4664 ino=0x1000000a14e state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b5dc0] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a470 [2,head] auth (dversion lock) v=4666 ino=0x1000000a470 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5bb180] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009d3b [2,head] auth (dversion lock) v=4668 ino=0x10000009d3b state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b5880] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a528 [2,head] auth (dversion lock) v=4670 ino=0x1000000a528 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5ba8c0] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a3ba [2,head] auth (dversion lock) v=4672 ino=0x1000000a3ba state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e59fb3340] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a3e5 [2,head] auth (dversion lock) v=4674 ino=0x1000000a3e5 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5bb500] was purgeable but no longer is!
2019-03-07T22:25:01.149 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a5ea [2,head] auth (dversion lock) v=4676 ino=0x1000000a5ea state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5ccba000] was purgeable but no longer is!
2019-03-07T22:25:01.150 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a63d [2,head] auth (dversion lock) v=4678 ino=0x1000000a63d state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b3a40] was purgeable but no longer is!
2019-03-07T22:25:01.150 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009fdf [2,head] auth (dversion lock) v=4680 ino=0x10000009fdf state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c5b2000] was purgeable but no longer is!
2019-03-07T22:25:01.151 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a586 [2,head] auth (dversion lock) v=4682 ino=0x1000000a586 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e59fb1c00] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a349 [2,head] auth (dversion lock) v=4684 ino=0x1000000a349 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e58ab6fc0] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a3fb [2,head] auth (dversion lock) v=4686 ino=0x1000000a3fb state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c960c40] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009d09 [2,head] auth (dversion lock) v=4688 ino=0x10000009d09 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e59fb2380] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a0d8 [2,head] auth (dversion lock) v=4690 ino=0x1000000a0d8 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c961a40] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a482 [2,head] auth (dversion lock) v=4692 ino=0x1000000a482 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5d74ea80] was purgeable but no longer is!
2019-03-07T22:25:01.152 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a533 [2,head] auth (dversion lock) v=4694 ino=0x1000000a533 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5d74f180] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009f65 [2,head] auth (dversion lock) v=4696 ino=0x10000009f65 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5e036e00] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a49d [2,head] auth (dversion lock) v=4698 ino=0x1000000a49d state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c1c6e00] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a0db [2,head] auth (dversion lock) v=4700 ino=0x1000000a0db state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5d74e700] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a4a8 [2,head] auth (dversion lock) v=4702 ino=0x1000000a4a8 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5db26c40] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a4c8 [2,head] auth (dversion lock) v=4704 ino=0x1000000a4c8 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5bbb08c0] was purgeable but no longer is!
2019-03-07T22:25:01.153 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a332 [2,head] auth (dversion lock) v=4706 ino=0x1000000a332 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5bbb0380] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a191 [2,head] auth (dversion lock) v=4708 ino=0x1000000a191 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c1c4c40] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a5ce [2,head] auth (dversion lock) v=4710 ino=0x1000000a5ce state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5e039180] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a30d [2,head] auth (dversion lock) v=4712 ino=0x1000000a30d state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5e038c40] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a4bf [2,head] auth (dversion lock) v=4714 ino=0x1000000a4bf state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5db29880] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009d24 [2,head] auth (dversion lock) v=4716 ino=0x10000009d24 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5d475c00] was purgeable but no longer is!
2019-03-07T22:25:01.154 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a38e [2,head] auth (dversion lock) v=4718 ino=0x1000000a38e state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5d6436c0] was purgeable but no longer is!
2019-03-07T22:25:01.155 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a33d [2,head] auth (dversion lock) v=4720 ino=0x1000000a33d state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5cd76c40] was purgeable but no longer is!
2019-03-07T22:25:01.155 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a30e [2,head] auth (dversion lock) v=4722 ino=0x1000000a30e state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5cd76000] was purgeable but no longer is!
2019-03-07T22:25:01.155 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/1000000a547 [2,head] auth (dversion lock) v=4724 ino=0x1000000a547 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5cd76700] was purgeable but no longer is!
2019-03-07T22:25:15.789 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:15.787 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray2/10000004524 [2,head] auth (dversion lock) v=5181 ino=0x10000004524 state=1879048192 | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c47b180] was purgeable but no longer is!
2019-03-07T22:25:20.741 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:25:20.748 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray5/1000000999f [2,head] auth (dversion lock) v=6359 ino=0x1000000999f state=1879048192 | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e57da7500] was purgeable but no longer is!
2019-03-07T22:27:12.304 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:12.314 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:27:12.304 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:12.314 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:27:26.020 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:26.030 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:27:26.021 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:26.030 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:27:33.605 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:33.615 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:27:55.639 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:27:55.650 7efd6e80a700 -1 mds.0.bal  balancer runs too long
2019-03-07T22:28:23.641 INFO:tasks.ceph.mds.b.smithi167.stderr:2019-03-07 22:28:23.653 7efd6e80a700 -1 mds.0.bal  balancer runs too long

From: /ceph/teuthology-archive/pdonnell-2019-03-07_15:13:09-multimds-wip-pdonnell-testing-20190307.041917-distro-basic-smithi/3679312/teuthology.log


Related issues

Copied to fs - Backport #39221: luminous: mds: behind on trimming and "[dentry] was purgeable but no longer is!" Resolved
Copied to fs - Backport #39222: nautilus: mds: behind on trimming and "[dentry] was purgeable but no longer is!" Resolved
Copied to fs - Backport #39223: mimic: mds: behind on trimming and "[dentry] was purgeable but no longer is!" Resolved

History

#1 Updated by Zheng Yan 7 months ago

For the "was purgeable but no longer is" errors.

2019-03-07 22:25:01.126 7efd6c005700 10 mds.0.cache.ino(0x10000009bc2) auth_pin by 0x555e5ddfa700 on [inode 0x10000009bc2 [2,head] ~mds0/stray6/10000009bc2 auth v4642 ap=1 dirtyparent s=0 nl=0 n(v0 rc2019-03-07 22:24:26.391179 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=1 0x555e5ddfa700] now 1
2019-03-07 22:25:01.126 7efd6c005700 20 mds.0.cache.ino(0x10000009bc2) store_backtrace: no dirtypool or no old pools
2019-03-07 22:25:01.126 7efd6c005700  1 -- [v2:172.21.15.167:6834/679747418,v1:172.21.15.167:6836/679747418] --> [v2:172.21.15.170:6816/6682,v1:172.21.15.170:6817/6682] -- osd_op(unknown.0.5:41412 3.5 3:b5d1c589:::10000009bc2.00000000:head [create,setxattr parent (99),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e20) v8 -- 0x555e5fa4bb80 con 0x555e52d7a000
2019-03-07 22:25:01.153 7efd6c005700 10 mds.0.cache.strays eval_stray [dentry #0x100/stray6/10000009bc2 [2,head] auth (dversion lock) v=4642 ino=0x10000009bc2 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c1c4fc0]
2019-03-07 22:25:01.153 7efd6c005700 10 mds.0.cache.strays  inode is [inode 0x10000009bc2 [2,head] ~mds0/stray6/10000009bc2 auth v4642 ap=1 dirtyparent s=0 nl=0 n(v0 rc2019-03-07 22:24:26.391179 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=1 0x555e5ddfa700]
2019-03-07 22:25:01.153 7efd6c005700 -1 mds.0.cache.strays Dentry [dentry #0x100/stray6/10000009bc2 [2,head] auth (dversion lock) v=4642 ino=0x10000009bc2 state=1879048193|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x555e5c1c4fc0] was purgeable but no longer is!

I think we can just remove the code that prints error

#2 Updated by Zheng Yan 7 months ago

The "behind on trimming" was caused by a frozen dirfrag. The dirfrag stayed in frozen state for a long time is because Migrator::handle_export_prep() took long time.

diff --git a/src/mds/Migrator.cc b/src/mds/Migrator.cc
index 180fb99b2d..59f721921c 100644
--- a/src/mds/Migrator.cc
+++ b/src/mds/Migrator.cc
@@ -2534,6 +2534,7 @@ void Migrator::handle_export_prep(const MExportDirPrep::const_ref &m, bool did_a
        if (!bound) {
          dout(7) << "  opening bounding dirfrag " << leaf << " on " << *in << dendl;
          cache->open_remote_dirfrag(in, leaf, cf.build());
+         // this may take long if there are lots of bounding dirfrags
          return;
        }

#3 Updated by Zheng Yan 7 months ago

  • Pull request ID set to 27051

#4 Updated by Zheng Yan 7 months ago

  • Status changed from New to Need Review

#5 Updated by Patrick Donnelly 6 months ago

  • Status changed from Need Review to Pending Backport

#6 Updated by Nathan Cutler 6 months ago

  • Copied to Backport #39221: luminous: mds: behind on trimming and "[dentry] was purgeable but no longer is!" added

#7 Updated by Nathan Cutler 6 months ago

  • Copied to Backport #39222: nautilus: mds: behind on trimming and "[dentry] was purgeable but no longer is!" added

#8 Updated by Nathan Cutler 6 months ago

  • Copied to Backport #39223: mimic: mds: behind on trimming and "[dentry] was purgeable but no longer is!" added

#9 Updated by Xiaoxi Chen 3 months ago

It seems not a valid fix as this is not the only path to have the error.

We hit this in another way, not due to frozen and migration but due to client has caps.


2019-07-10 03:27:51.458 7fc882aac700 10 mds.9.cache.strays  inode is [inode 0xa0001908553 [2,head] ~mds9/stray2/a0001908553 auth v12728687 s=7890291 nl=0 n(v0 rc2019-07-10 02:39:11.984908 b7890291 1=1+0) (iversion lock) caps={217702=pAsLsXsFscr/-@6} | ptrwaiter=0 request=0 lock=0 caps=1 dirtyparent=0 dirty=0 waiter=0 authpin=0 0x55a7342f9100]
2019-07-10 03:27:51.458 7fc882aac700 20 mds.9.cache.strays  caps | leases
2019-07-10 03:27:51.458 7fc882aac700 -1 mds.9.cache.strays Dentry [dentry #0x109/stray2/a0001908553 [2,head] auth (dversion lock) v=12728687 ino=0xa0001908553 state=1342177280 | request=0 lock=0 inodepin=1 dirty=0 authpin=0 0x55a86e584f00] was purgeable but no longer is!

#10 Updated by Xiaoxi Chen 3 months ago

root@cal-rno-mds-new-27:~# ceph daemon --cluster rno_ceph_cal mds.`hostname -s` dump inode 0xa0001908553
{
    "path": "~mds9/stray2/a0001908553",
    "ino": 10995142526291,
    "rdev": 0,
    "ctime": "2019-07-10 02:39:11.984908",
    "btime": "2019-07-09 06:33:06.046917",
    "mode": 33188,
    "uid": 0,
    "gid": 0,
    "nlink": 0,
    "dir_layout": {
        "dir_hash": 0
    },
    "layout": {
        "stripe_unit": 4194304,
        "stripe_count": 1,
        "object_size": 4194304,
        "pool_id": 2,
        "pool_ns": "" 
    },
    "old_pools": [],
    "size": 7890291,
    "truncate_seq": 1,
    "truncate_size": 18446744073709551615,
    "truncate_from": 0,
    "truncate_pending": 0,
    "mtime": "2019-07-09 06:34:49.419935",
    "atime": "2019-07-09 06:33:06.046917",
    "time_warp_seq": 0,
    "change_attr": 1,
    "export_pin": -1,
    "client_ranges": [],
    "dirstat": {
        "version": 0,
        "mtime": "0.000000",
        "num_files": 0,
        "num_subdirs": 0
    },
    "rstat": {
        "version": 0,
        "rbytes": 7890291,
        "rfiles": 1,
        "rsubdirs": 0,
        "rsnaps": 0,
        "rctime": "2019-07-10 02:39:11.984908" 
    },
    "accounted_rstat": {
        "version": 0,
        "rbytes": 7890291,
        "rfiles": 1,
        "rsubdirs": 0,
        "rsnaps": 0,
        "rctime": "2019-07-10 02:39:11.984908" 
    },
    "version": 12728687,
    "file_data_version": 0,
    "xattr_version": 1,
    "backtrace_version": 12728687,
    "stray_prior_path": "ORIGNIAL_PATH_HIDDEN",
    "symlink": "",
    "old_inodes": [],
    "dirfragtree": {
        "splits": []
    },
    "is_auth": true,
    "auth_state": {
        "replicas": {}
    },
    "replica_state": {
        "authority": [
            9,
            -2
        ],
        "replica_nonce": 0
    },
    "auth_pins": 0,
    "is_frozen": false,
    "is_freezing": false,
    "pins": {
        "ptrwaiter": 0,
        "request": 0,
        "lock": 0,
        "caps": 1,
        "dirtyparent": 0,
        "dirty": 0,
        "waiter": 0,
        "authpin": 0
    },
    "nref": 1,
    "versionlock": {
        "gather_set": [],
        "is_leased": false,
        "num_rdlocks": 0,
        "num_wrlocks": 0,
        "num_xlocks": 0,
        "xlock_by": {}
    },
    "authlock": {},
    "linklock": {},
    "dirfragtreelock": {},
    "filelock": {},
    "xattrlock": {},
    "snaplock": {},
    "nestlock": {
        "gather_set": [],
        "is_leased": false,
        "num_rdlocks": 0,
        "num_wrlocks": 0,
        "num_xlocks": 0,
        "xlock_by": {}
    },
    "flocklock": {},
    "policylock": {},
    "states": [
        "auth",
        "notifyref",
        "orphan" 
    ],
    "client_caps": [
        {
            "client_id": 217702,
            "pending": "pAsLsXsFscr",
            "issued": "pAsLsXsFscr",
            "wanted": "-",
            "last_sent": 6
        }
    ],
    "loner": -1,
    "want_loner": -1,
    "mds_caps_wanted": []
}

#11 Updated by Zheng Yan 3 months ago

not big issue even inode becomes to have caps

#12 Updated by Xiaoxi Chen 3 months ago

I think we need to try reclaim the caps in this case. I am seeing num_stray accumulated in my env due to the indoes have caps.

The clients that holding the caps are the cleanup clients --- i.e the one that trigger the unlink. What it does and only does is
find /import/ceph/callogs/ -maxdepth 3 -type f -name *.mul.gz -cmin +1200
so the fd should closed and caps can be released however it doesnt.

echo 3 > /proc/sys/vm/drop_caches on client side solve the issue, also shrink the #inodes in cache(fuse) from 1.7M down to 93k.

#13 Updated by Zheng Yan 3 months ago

is cephfs exported to nfs

#14 Updated by Xiaoxi Chen 3 months ago

Zheng Yan wrote:

is cephfs exported to nfs

No, it is ceph-fuse (13.2.5).

It seems like customer has ~10 nodes mounted same share, all do something like
"find /import/ceph/callogs/ -maxdepth 3 -type f -name *.mul.gz -cmin +1200 -exec rm -f {} + " but it is a hand written java application...

We did a change this afternoon that 1) reduce concurrent from 10 to 2; 2) change from fuse to kernel and is seeing positive result.

Also, reducing mds_max_caps_per_client helps. So it seems like the ll_forget in ceph-fuse is not get called from kernel to release caps for the deleted file?

#15 Updated by Nathan Cutler 3 days ago

  • Status changed from Pending Backport to Resolved

While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".

Also available in: Atom PDF