Project

General

Profile

Bug #25049

MDS journal flush too often and resulted in backlog

Added by Chuan Qiu 5 months ago. Updated 5 months ago.

Status:
Need More Info
Priority:
Normal
Assignee:
Category:
-
Target version:
Start date:
07/21/2018
Due date:
% Done:

0%

Source:
Community (user)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
fs
Component(FS):
MDS
Labels (FS):
Pull request ID:

Description

When doing some operation like rmtree, the MDS get stuck because flush journal too often and the OSD for metadata have a very long backlog, each op is repeately retrying itself.

On one of the OSD:

There are 1425 tasks, each one is like the following.

{
            "description": "osd_op(mds.0.65947:1338289 6.3e1 6:87fe1a88:::200.0007442f:head [write 397676~1943 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e167997)",
            "initiated_at": "2018-07-20 23:54:24.320047",
            "age": 302.367188,
            "duration": 302.367205,
            "type_data": {
                "flag_point": "delayed",
                "events": [
                    {
                        "time": "2018-07-20 23:54:24.320047",
                        "event": "initiated" 
                    },
                    {
                        "time": "2018-07-20 23:54:24.320111",
                        "event": "queued_for_pg" 
                    },
                    {
                        "time": "2018-07-20 23:54:24.320147",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:54:24.320196",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:15.504925",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:15.504932",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:25.153420",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:25.153428",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:29.685143",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:29.685149",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:32.303080",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:32.303088",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:36.824319",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:36.824327",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:42.114700",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:42.114707",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:46.972434",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:46.972441",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:52.208524",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:52.208531",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:55:56.218001",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:55:56.218007",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:01.593335",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:01.593343",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:06.182136",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:06.182143",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:10.789066",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:10.789070",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:13.242845",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:13.242853",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:17.406025",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:17.406032",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:19.529955",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:19.529962",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:25.369497",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:25.369504",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:31.130066",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:31.130074",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:33.086413",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:33.086420",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:37.646741",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:37.646751",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:40.651399",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:40.651405",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:42.710959",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:42.710967",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:45.510792",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:45.510802",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:50.850666",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:50.850673",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:52.900567",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:52.900575",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:56:58.148878",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:56:58.148885",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:02.356166",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:02.356173",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:07.136997",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:07.137007",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:12.709157",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:12.709165",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:17.040579",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:17.040588",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:21.180869",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:21.180877",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:23.606386",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:23.606394",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:25.397037",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:25.397044",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:28.062248",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:28.062256",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:30.447311",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:30.447321",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:33.000073",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:33.000080",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:37.622278",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:37.622285",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:42.134795",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:42.134802",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:45.275269",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:45.275276",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:47.475963",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:47.475982",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:52.845520",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:52.845527",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:55.209436",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:55.209445",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.858314",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.858321",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.901728",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.901736",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.997507",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:57:59.997514",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.089125",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.089131",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.124914",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.124919",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.174639",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.174644",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.225405",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.225412",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.258350",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.258357",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.279925",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.279931",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.297703",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.297709",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.314106",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.314111",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.351150",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.351157",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.397878",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.397891",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.431007",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.431013",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.475729",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.475736",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.525501",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:00.525511",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:03.032572",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:03.032579",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:05.466303",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:05.466311",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:11.059212",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:11.059220",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:13.557244",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:13.557254",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:18.322574",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:18.322582",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:24.166932",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:24.166940",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:29.250585",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:29.250593",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:31.790902",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:31.790910",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:37.459207",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:37.459217",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:42.897767",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:42.897774",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:47.962588",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:47.962596",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:52.965549",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:52.965557",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:58:57.975095",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:58:57.975103",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:03.768679",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:03.768689",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.180119",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.180126",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.214348",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.214355",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.262987",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:06.262994",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:14.612876",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:14.612883",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:17.912213",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:17.912220",
                        "event": "waiting for rw locks" 
                    },
                    {
                        "time": "2018-07-20 23:59:23.774640",
                        "event": "reached_pg" 
                    },
                    {
                        "time": "2018-07-20 23:59:23.774648",
                        "event": "waiting for rw locks" 
                    }
                ]
            }
        },

History

#1 Updated by Zheng Yan 5 months ago

I need some mds.log, to check why mds flushes log.

#2 Updated by Patrick Donnelly 5 months ago

  • Status changed from New to Need More Info
  • Assignee set to Zheng Yan
  • Target version set to v14.0.0
  • Source set to Community (user)

Also available in: Atom PDF