Uploaded image for project: 'Lustre'
  1. Lustre
  2. LU-8633

SIGBUS under memory pressure with fast_read enabled

Details

    • Bug
    • Resolution: Fixed
    • Critical
    • Lustre 2.9.0
    • Lustre 2.8.0, Lustre 2.9.0
    • 3
    • 9223372036854775807

    Description

      Recently we have some Intel Xeon-Phi Knights Landing boxes up and running, but we have applications crashing with SIGBUS.
      Steps to reproduce:
      Put the Xeon-Phi MCDRAM to flat mode

      [15:10:32 root@r3641:~] # cat /proc/cpuinfo
      processor       : 0
      vendor_id       : GenuineIntel
      cpu family      : 6
      model           : 87
      model name      : Intel(R) Xeon Phi(TM) CPU 7230 @ 1.30GHz
      stepping        : 1
      microcode       : 0x130
      cpu MHz         : 1177.769
      cache size      : 1024 KB
      physical id     : 0
      siblings        : 256
      core id         : 0
      cpu cores       : 64
      apicid          : 0
      initial apicid  : 0
      fpu             : yes
      fpu_exception   : yes
      cpuid level     : 13
      wp              : yes
      flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms avx512f rdseed adx avx512pf avx512er avx512cd xsaveopt
      bugs            :
      bogomips        : 2600.01
      clflush size    : 64
      cache_alignment : 64
      address sizes   : 46 bits physical, 48 bits virtual
      power management:
      [...thousands of lines omitted...]
      [15:10:36 root@r3641:~] # numactl -H
      available: 2 nodes (0-1)
      node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255
      node 0 size: 193304 MB
      node 0 free: 190405 MB
      node 1 cpus:
      node 1 size: 16125 MB
      node 1 free: 15889 MB
      node distances:
      node   0   1 
        0:  10  31 
        1:  31  10 
      

      We have two numa nodes here, node 0 has all the cpus and memory,
      node 1 is the MCDRAM.

      Run the stream benchmark: https://www.cs.virginia.edu/stream/
      on numa node 1 with 64 threads, the stream binary itself is on the lustre filesystem.

      [15:12:45 root@r3641:~] # export OMP_NUM_THREADS=64
      [15:15:10 root@r3641:~] # numactl -m 1 /system/Benchmarks/stream/5.10-Intel-Opt/stream-nci-icc.exe 
      -------------------------------------------------------------
      STREAM version $Revision: 5.10 $
      -------------------------------------------------------------
      This system uses 8 bytes per array element.
      -------------------------------------------------------------
      Array size = 6405100800 (elements), Offset = 0 (elements)
      Memory per array = 48867.0 MiB (= 47.7 GiB).
      Total memory required = 146601.1 MiB (= 143.2 GiB).
      Each kernel will be executed 10 times.
       The *best* time for each kernel (excluding the first iteration)
       will be used to compute the reported bandwidth.
      -------------------------------------------------------------
      Number of Threads requested = 64
      Number of Threads counted = 64
      Bus error
      

      and it got killed with SIGBUS

      [ 1472.651904] potentially unexpected fatal signal 7.
      [ 1472.656784] CPU: 28 PID: 10226 Comm: stream-nci-icc. Tainted: G           O    4.4.16-raijin.el6.x86_64 #1
      [ 1472.666492] Hardware name: Supermicro C2112-4KL1/MBD-K1SPI-P, BIOS 1.0a 06/11/2016
      [ 1472.674120] task: ffff883421770000 ti: ffff882ed0f6c000 task.ti: ffff882ed0f6c000
      [ 1472.681655] RIP: 0033:[<00000000004023ee>]  [<00000000004023ee>] 0x4023ee
      [ 1472.688527] RSP: 002b:00007fec4fbfcd80  EFLAGS: 00010206
      [ 1472.693892] RAX: 00000017dcc1b600 RBX: 000000000000001c RCX: 0000000000a33518
      [ 1472.701087] RDX: 0000000bee910e00 RSI: 00000000a706a930 RDI: 0000000000606600
      [ 1472.708275] RBP: 00007fec4fbfd0f0 R08: 0000000005f71850 R09: 0000000000000000
      [ 1472.715469] R10: 00000000a706a930 R11: 00000000a7a9de40 R12: 0000000005f71854
      [ 1472.722656] R13: 0000000000404880 R14: 0000000000000000 R15: 000000000000001c
      [ 1472.729843] FS:  00007fec4fbfe500(0000) GS:ffff882f7e180000(0000) knlGS:0000000000000000
      [ 1472.738133] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
      [ 1472.744090] CR2: 00000000004023ee CR3: 0000003420bdf000 CR4: 00000000001406e0
      

      It was handling a page fault on addr 4023ee which is inside the binary itself.
      Turning off fast_read will make the problem go away:

      lctl set_param llite.*.fast_read=0
      

      In ll_fault0, with fast_read enabled, it calls filemap_fault() right away,

      	if (ll_sbi_has_fast_read(ll_i2sbi(file_inode(vma->vm_file)))) {
      		/* do fast fault */
      		ll_cl_add(vma->vm_file, env, NULL, LCC_MMAP);
      		fault_ret = filemap_fault(vma, vmf);
      		ll_cl_remove(vma->vm_file, env);
      
      		/* - If there is no error, then the page was found in cache and
      		 *   uptodate;
      		 * - If VM_FAULT_RETRY is set, the page existed but failed to
      		 *   lock. It will return to kernel and retry;
      		 * - Otherwise, it should try normal fault under DLM lock. */
      		if ((fault_ret & VM_FAULT_RETRY) ||
      		    !(fault_ret & VM_FAULT_ERROR))
      			GOTO(out, result = 0);
      
      		fault_ret = 0;b
      
      	}
      

      filemap_fault() calls find_get_page() which fails to find the page in page cache because we are under memory pressure, so filemap_fault() tries page_cache_read() which allocate a page, add it to page cache lru and then calls ll_readpage(). ll_readpage will fail for fast_read, so we fall back to normal fault in ll_fault0().

      So we init a cl_io and does cl_io_loop, then we reach filemap_fault() for the second time, from vvp_io_kernel_fault()
      This time we can find the page in the page cache, because we just created it in the first call to filemap_fault(). But the page is not up to date,
      so we call ll_readpage() again, then sleep on the page until the page is unlocked.

      page_not_uptodate:
      	/*
      	 * Umm, take care of errors if the page isn't up-to-date.
      	 * Try to re-read it _once_. We do this synchronously,
      	 * because there really aren't any performance issues here
      	 * and we need to check for errors.
      	 */
      	ClearPageError(page);
      	error = mapping->a_ops->readpage(file, page);
      	if (!error) {
      		wait_on_page_locked(page);
      		if (!PageUptodate(page))
      			error = -EIO;
      	}
      	put_page(page);
      
      	if (!error || error == AOP_TRUNCATED_PAGE)
      		goto retry_find;
      
      	/* Things didn't work out. Return zero to tell the mm layer so. */
      	shrink_readahead_size_eio(file, ra);
      	return VM_FAULT_SIGBUS;
      

      When ptlrpcd thread finishes the io, calls cl_page_export() to export the page and then unlocks the page, which will wake up the page fault thread waiting on the page. Before the page fault thread wakes up and continues, osc_lru_shrink kicks in because of memory pressure, it picks the just completed page, and kicks it out. when the page fault thread finally got a chance, it looks at the page and it's not up to date anymore. This leads page handler to fail with a SIGBUS.
      The reason turning off fast_read works is without fast_read,
      we only call filemap_fault() doing normal fault, where the first call to ll_readpage() will succeed and we will not reach the code label page_not_uptodate which does the waiting and checking for uptodate.

      IMHO we should fix osc_lru_shrink, it's ok for fiemap_fault wait on the page and check if it's up to date. we need to make sure the page doesn't go away in the whole process.

      Attachments

        Issue Links

          Activity

            [LU-8633] SIGBUS under memory pressure with fast_read enabled

            Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/22827/
            Subject: LU-8633 llite: do not clear uptodate bit in page delete
            Project: fs/lustre-release
            Branch: master
            Current Patch Set:
            Commit: 27c079d110cc2867dc0db8452695f37c24f77215

            gerrit Gerrit Updater added a comment - Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/22827/ Subject: LU-8633 llite: do not clear uptodate bit in page delete Project: fs/lustre-release Branch: master Current Patch Set: Commit: 27c079d110cc2867dc0db8452695f37c24f77215

            just my 2c, but http://review.whamcloud.com/22827 also seems to have fixed some sigbus under memory pressure problems we've been having with ganglia's gmond on 2.7.0 on el6 recently. the patch also seems to work fine so far with 2.8.0 on el6.

            cheers,
            robin

            rjh Robin Humble (Inactive) added a comment - just my 2c, but http://review.whamcloud.com/22827 also seems to have fixed some sigbus under memory pressure problems we've been having with ganglia's gmond on 2.7.0 on el6 recently. the patch also seems to work fine so far with 2.8.0 on el6. cheers, robin

            Not to my knowledge, maybe just tried to clean up things better.

            jay Jinshan Xiong (Inactive) added a comment - Not to my knowledge, maybe just tried to clean up things better.

            Hi Jinshan,
            Thanks for the background reading links, that was a lot to read.
            I just gave 22827 a try and it fixed the problem. I also noticed the call to ClearPageUptodate was added in commit 0a259bd7
            Is there a reason it got added to vvp_page_delete()?

            lidongyang Li Dongyang (Inactive) added a comment - Hi Jinshan, Thanks for the background reading links, that was a lot to read. I just gave 22827 a try and it fixed the problem. I also noticed the call to ClearPageUptodate was added in commit 0a259bd7 Is there a reason it got added to vvp_page_delete()?

            Hi Jinshan,
            I'm on medical leave recently, will test the patch when I'm back to work.
            Thanks

            lidongyang Li Dongyang (Inactive) added a comment - Hi Jinshan, I'm on medical leave recently, will test the patch when I'm back to work. Thanks

            Jinshan Xiong (jinshan.xiong@intel.com) uploaded a new patch: http://review.whamcloud.com/22827
            Subject: LU-8633 llite: do not clear uptodate bit in page delete
            Project: fs/lustre-release
            Branch: master
            Current Patch Set: 1
            Commit: a6afade3e36957907c713f8e143943341102ed71

            gerrit Gerrit Updater added a comment - Jinshan Xiong (jinshan.xiong@intel.com) uploaded a new patch: http://review.whamcloud.com/22827 Subject: LU-8633 llite: do not clear uptodate bit in page delete Project: fs/lustre-release Branch: master Current Patch Set: 1 Commit: a6afade3e36957907c713f8e143943341102ed71

            Hi Dongyang,

            Can you please try if the following patch can fix this issue:

            diff --git a/lustre/llite/vvp_page.c b/lustre/llite/vvp_page.c
            index ec050f5..f6e0cea 100644
            --- a/lustre/llite/vvp_page.c
            +++ b/lustre/llite/vvp_page.c
            @@ -171,7 +171,6 @@ static void vvp_page_delete(const struct lu_env *env,
                    refc = atomic_dec_return(&page->cp_ref);
                    LASSERTF(refc >= 1, "page = %p, refc = %d\n", page, refc);
             
            -       ClearPageUptodate(vmpage);
                    ClearPagePrivate(vmpage);
                    vmpage->private = 0;
                    /*
            
            jay Jinshan Xiong (Inactive) added a comment - Hi Dongyang, Can you please try if the following patch can fix this issue: diff --git a/lustre/llite/vvp_page.c b/lustre/llite/vvp_page.c index ec050f5..f6e0cea 100644 --- a/lustre/llite/vvp_page.c +++ b/lustre/llite/vvp_page.c @@ -171,7 +171,6 @@ static void vvp_page_delete( const struct lu_env *env, refc = atomic_dec_return(&page->cp_ref); LASSERTF(refc >= 1, "page = %p, refc = %d\n" , page, refc); - ClearPageUptodate(vmpage); ClearPagePrivate(vmpage); vmpage-> private = 0; /*

            Hi Dongyang,

            Please refer to LU-4841 and commit 48eceeec98da3db2c93d980bb5f7e1c1f7c333cc where I added a tunable ccc_unstable_check and it's disabled by default for performance reason.

            jay Jinshan Xiong (Inactive) added a comment - Hi Dongyang, Please refer to LU-4841 and commit 48eceeec98da3db2c93d980bb5f7e1c1f7c333cc where I added a tunable ccc_unstable_check and it's disabled by default for performance reason.

            If an extra cl_page ref could be taken during page fault, it can also fix the problem. However I don't see where is the best place to do this.

            I'm worrying about there would be performance impact with the proposed method. We need to turn on unstable_check to make lru_page_busy() work reasonably. Otherwise, since there are lots of pages being held and waiting for trans to be committed, no new pages can be added into OSC LRU cache.

            I will ask someone on our team to run some performance benchmark against your patch. Meanwhile, can you please create a patch that takes page refcount in fault routine?

            jay Jinshan Xiong (Inactive) added a comment - If an extra cl_page ref could be taken during page fault, it can also fix the problem. However I don't see where is the best place to do this. I'm worrying about there would be performance impact with the proposed method. We need to turn on unstable_check to make lru_page_busy() work reasonably. Otherwise, since there are lots of pages being held and waiting for trans to be committed, no new pages can be added into OSC LRU cache. I will ask someone on our team to run some performance benchmark against your patch. Meanwhile, can you please create a patch that takes page refcount in fault routine?

            I've got the life cycle of the cl_page, here it is:
            The cl_page is created by ll_readpage calling cl_page_find:

            00000020:00000001:25.0:1471329003.206114:0:14684:0:(cl_page.c:179:cl_page_alloc()) Process entered
            00000020:00000010:25.0:1471329003.206121:0:14684:0:(cl_page.c:181:cl_page_alloc()) kmalloced 'page': 448 at ffff881902655800.
            00000020:00000001:25.0:1471329003.206129:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered
            00000020:00000001:25.0:1471329003.206134:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving
            00020000:00000001:25.0:1471329003.206141:0:14684:0:(lov_page.c:83:lov_page_init_raid0()) Process entered
            00000020:00000001:25.0:1471329003.206148:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered
            00000020:00000001:25.0:1471329003.206152:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving
            00020000:00000001:25.0:1471329003.206157:0:14684:0:(lov_io.c:212:lov_sub_get()) Process entered
            00020000:00000001:25.0:1471329003.206163:0:14684:0:(lov_io.c:223:lov_sub_get()) Process leaving (rc=18446612239660200384 : -131834049351232 : ffff8818fe51b1c0)
            00020000:00000001:25.0:1471329003.206173:0:14684:0:(lovsub_page.c:68:lovsub_page_init()) Process entered
            00000020:00000001:25.0:1471329003.206179:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered
            00000020:00000001:25.0:1471329003.206184:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving
            00020000:00000001:25.0:1471329003.206189:0:14684:0:(lovsub_page.c:71:lovsub_page_init()) Process leaving (rc=0 : 0 : 0)
            00000008:00000001:25.0:1471329003.206199:0:14684:0:(osc_cache.c:2272:osc_prep_async_page()) Process entered
            00000008:00000040:25.0:1471329003.206208:0:14684:0:(osc_cache.c:2293:osc_prep_async_page()) oap ffff881902655928 page ffffea0066a8dc00 obj off 0
            00000008:00000001:25.0:1471329003.206216:0:14684:0:(osc_cache.c:2294:osc_prep_async_page()) Process leaving (rc=0 : 0 : 0)
            00000020:00000001:25.0:1471329003.206224:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered
            00000020:00000001:25.0:1471329003.206229:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving
            00000008:00000001:25.0:1471329003.206235:0:14684:0:(osc_page.c:765:osc_lru_alloc()) Process entered
            00000008:00000001:25.0:1471329003.206267:0:14684:0:(osc_page.c:799:osc_lru_alloc()) Process leaving (rc=0 : 0 : 0)
            00020000:00000001:25.0:1471329003.206277:0:14684:0:(lov_page.c:110:lov_page_init_raid0()) Process leaving (rc=0 : 0 : 0)
            00000020:00000001:25.0:1471329003.206284:0:14684:0:(cl_page.c:217:cl_page_alloc()) Process leaving (rc=18446612239728596992 : -131833980954624 : ffff881902655800)
            00000020:00000001:25.0:1471329003.206293:0:14684:0:(cl_page.c:272:cl_page_find()) Process leaving (rc=18446612239728596992 : -131833980954624 : ffff881902655800)
            

            The ref is set to 1 after allocation and bumped up by vvp_page_init() during init.
            Then cl_page_assume() is called by ll_readpage() to set the owner:

            00000020:00000001:25.0:1471329003.206302:0:14684:0:(cl_page.c:657:cl_page_assume()) Process entered
            00000020:00000001:25.0:1471329003.206308:0:14684:0:(cl_io.c:1130:cl_io_top()) Process entered
            00000020:00000001:25.0:1471329003.206313:0:14684:0:(cl_io.c:1133:cl_io_top()) Process leaving (rc=18446612239827533920 : -131833882017696 : ffff8819084b0060)
            00000020:00000001:25.0:1471329003.206321:0:14684:0:(cl_page.c:501:cl_page_invoid()) Process entered
            00000020:00000001:25.0:1471329003.206327:0:14684:0:(cl_page.c:505:cl_page_invoid()) Process leaving
            00000020:00000001:25.0:1471329003.206332:0:14684:0:(cl_io.c:1130:cl_io_top()) Process entered
            00000020:00000001:25.0:1471329003.206337:0:14684:0:(cl_io.c:1133:cl_io_top()) Process leaving (rc=18446612239827533920 : -131833882017696 : ffff8819084b0060)
            00000020:00000001:25.0:1471329003.206345:0:14684:0:(cl_page.c:521:cl_page_owner_set()) Process entered
            00000020:00000001:25.0:1471329003.206357:0:14684:0:(cl_page.c:524:cl_page_owner_set()) Process leaving
            00000020:00000001:25.0:1471329003.206363:0:14684:0:(cl_page.c:328:cl_page_state_set0()) Process entered
            00000020:00000001:25.0:1471329003.206376:0:14684:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[2 ffff8800b214f9d0 0 1 ffff8819084b0060]
            00000020:00000001:25.0:1471329003.206383:0:14684:0:(cl_page.c:331:cl_page_state_set0()) 0 -> 1
            00000020:00000001:25.0:1471329003.206389:0:14684:0:(cl_page.c:338:cl_page_state_set0()) Process leaving
            00000020:00000001:25.0:1471329003.206395:0:14684:0:(cl_page.c:665:cl_page_assume()) Process leaving
            

            Now the cl_page has a ref of 2, with a CPS_OWNED state and CPT_CACHEABLE type.
            The ref got up again in ll_readpage->ll_io_read_page->cl_2quque_add->cl_page_list_add, the ref becomes 3.
            Later the cl_page_prep() is called by osc_io_submit()

            00000020:00000001:25.0:1471329003.206731:0:14684:0:(cl_io.c:680:cl_io_submit_rw()) Process entered
            00000008:00400020:25.0:1471329003.206759:0:14684:0:(osc_io.c:146:osc_io_submit()) 1 0
            00000080:00000001:25.0:1471329003.206775:0:14684:0:(vvp_page.c:207:vvp_page_prep_read()) Process entered
            00000080:00000001:25.0:1471329003.206800:0:14684:0:(vvp_page.c:209:vvp_page_prep_read()) Process leaving (rc=0 : 0 : 0)
            00000020:00000001:25.0:1471329003.206808:0:14684:0:(cl_page.c:493:cl_page_invoke()) Process leaving (rc=0 : 0 : 0)
            00000020:00000001:25.0:1471329003.206815:0:14684:0:(cl_page.c:853:cl_page_io_start()) Process entered
            00000020:00000001:25.0:1471329003.206821:0:14684:0:(cl_page.c:510:cl_page_owner_clear()) Process entered
            00000020:00000001:25.0:1471329003.206826:0:14684:0:(cl_page.c:516:cl_page_owner_clear()) Process leaving
            00000020:00000001:25.0:1471329003.206831:0:14684:0:(cl_page.c:843:cl_req_type_state()) Process entered
            00000020:00000001:25.0:1471329003.206836:0:14684:0:(cl_page.c:844:cl_req_type_state()) Process leaving (rc=3 : 3 : 3)
            00000020:00000001:25.0:1471329003.206844:0:14684:0:(cl_page.c:328:cl_page_state_set0()) Process entered
            00000020:00000001:25.0:1471329003.206857:0:14684:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[3 ffff8800b214f9d0 1 1           (null)]
            00000020:00000001:25.0:1471329003.206864:0:14684:0:(cl_page.c:331:cl_page_state_set0()) 1 -> 3
            00000020:00000001:25.0:1471329003.206870:0:14684:0:(cl_page.c:338:cl_page_state_set0()) Process leaving
            00000020:00000001:25.0:1471329003.206875:0:14684:0:(cl_page.c:856:cl_page_io_start()) Process leaving
            00000020:00000001:25.0:1471329003.206886:0:14684:0:(cl_page.c:889:cl_page_prep()) page@ffff881902655800[3 ffff8800b214f9d0 3 1           (null)]
            00000020:00000001:25.0:1471329003.206893:0:14684:0:(cl_page.c:889:cl_page_prep()) 0 0
            

            The owner is cleared, and the state changed from CPS_OWNED to CPS_PAGEIN
            Then there is a get on the page in osc_page_submit and put on the page by cl_page_list_del as page->cp_sync_io is NULL

            00000020:00000001:25.0:1471329003.206902:0:14684:0:(cl_page.c:357:cl_page_get()) Process entered
            00000020:00000001:25.0:1471329003.206906:0:14684:0:(cl_page.c:359:cl_page_get()) Process leaving
            00000020:00000001:25.0:1471329003.206913:0:14684:0:(cl_page.c:826:cl_page_is_vmlocked()) Process entered
            00000020:00000001:25.0:1471329003.206919:0:14684:0:(cl_page.c:837:cl_page_is_vmlocked()) Process leaving (rc=1 : 1 : 1)
            00000020:00000001:25.0:1471329003.206926:0:14684:0:(cl_io.c:892:cl_page_list_del()) Process entered
            00000020:00000001:25.0:1471329003.206931:0:14684:0:(cl_page.c:374:cl_page_put()) Process entered
            00000020:00000001:25.0:1471329003.206941:0:14684:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[4 ffff8800b214f9d0 3 1           (null)]
            00000020:00000001:25.0:1471329003.206947:0:14684:0:(cl_page.c:376:cl_page_put()) 4
            00000020:00000001:25.0:1471329003.206952:0:14684:0:(cl_page.c:391:cl_page_put()) Process leaving
            00000020:00000001:25.0:1471329003.206957:0:14684:0:(cl_io.c:897:cl_page_list_del()) Process leaving
            

            And a put when we return to ll_readpage, now the ref is 2

            00000080:00000001:25.0:1471329003.207246:0:14684:0:(rw.c:1136:ll_io_read_page()) Process leaving (rc=0 : 0 : 0)
            00000020:00000001:25.0:1471329003.207253:0:14684:0:(cl_page.c:374:cl_page_put()) Process entered
            00000020:00000001:25.0:1471329003.207266:0:14684:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[3 ffff8800b214f9d0 3 1           (null)]
            00000020:00000001:25.0:1471329003.207273:0:14684:0:(cl_page.c:376:cl_page_put()) 3
            00000020:00000001:25.0:1471329003.207279:0:14684:0:(cl_page.c:391:cl_page_put()) Process leaving
            00000080:00000001:25.0:1471329003.207284:0:14684:0:(rw.c:1223:ll_readpage()) Process leaving (rc=0 : 0 : 0)
            

            After this the thread is waiting in filemap_fault.
            Now the ptlrpcd thread, when the io is done, osc_completion is called, first it calls cl_page_completion and then cl_put_page

            00000008:00000001:25.0:1471329003.210591:0:2904:0:(osc_cache.c:1318:osc_completion()) Process entered
            00000020:00000001:25.0:1471329003.210597:0:2904:0:(cl_page.c:843:cl_req_type_state()) Process entered
            00000020:00000001:25.0:1471329003.210613:0:2904:0:(cl_page.c:844:cl_req_type_state()) Process leaving (rc=3 : 3 : 3)
            00000020:00000001:25.0:1471329003.210621:0:2904:0:(cl_page.c:917:cl_page_completion()) Process entered
            00000020:00000001:25.0:1471329003.210632:0:2904:0:(cl_page.c:918:cl_page_completion()) page@ffff881902655800[2 ffff8800b214f9d0 3 1           (null)]
            00000020:00000001:25.0:1471329003.210638:0:2904:0:(cl_page.c:918:cl_page_completion()) 0 0
            00000020:00000001:25.0:1471329003.210645:0:2904:0:(cl_page.c:328:cl_page_state_set0()) Process entered
            00000020:00000001:25.0:1471329003.210656:0:2904:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[2 ffff8800b214f9d0 3 1           (null)]
            00000020:00000001:25.0:1471329003.210661:0:2904:0:(cl_page.c:331:cl_page_state_set0()) 3 -> 0
            00000020:00000001:25.0:1471329003.210667:0:2904:0:(cl_page.c:338:cl_page_state_set0()) Process leaving
            00000080:00000001:25.0:1471329003.210687:0:2904:0:(vvp_page.c:262:vvp_page_completion_read()) Process entered
            00000080:00008000:25.0:1471329003.210699:0:2904:0:(vvp_page.c:265:vvp_page_completion_read()) page@ffff881902655800[2 ffff8800b214f9d0 0 1           (null)]
            00000080:00008000:25.0:1471329003.210705:0:2904:0:(vvp_page.c:265:vvp_page_completion_read()) completing READ with 0
            00000080:00000001:25.0:1471329003.210852:0:2904:0:(vvp_page.c:280:vvp_page_completion_read()) Process leaving
            00000020:00000001:25.0:1471329003.210859:0:2904:0:(cl_page.c:930:cl_page_completion()) Process leaving
            00000020:00000001:25.0:1471329003.210866:0:2904:0:(cl_page.c:374:cl_page_put()) Process entered
            00000020:00000001:25.0:1471329003.210887:0:2904:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[2 ffff8800b214f9d0 0 1           (null)]
            00000020:00000001:25.0:1471329003.210894:0:2904:0:(cl_page.c:376:cl_page_put()) 2
            00000020:00000001:25.0:1471329003.210900:0:2904:0:(cl_page.c:391:cl_page_put()) Process leaving
            00000008:00000001:25.0:1471329003.210905:0:2904:0:(osc_cache.c:1356:osc_completion()) Process leaving (rc=0 : 0 : 0)
            

            The state is set to CPS_CACHED, then the page is exported to vm, finally the ref is dropped to 1.
            Now if osc_lru_shrink kicks in, lru_page_busy will fail the check.

            If an extra cl_page ref could be taken during page fault, it can also fix the problem. However I don't see where is the best place to do this.
            Thanks

            lidongyang Li Dongyang (Inactive) added a comment - I've got the life cycle of the cl_page, here it is: The cl_page is created by ll_readpage calling cl_page_find: 00000020:00000001:25.0:1471329003.206114:0:14684:0:(cl_page.c:179:cl_page_alloc()) Process entered 00000020:00000010:25.0:1471329003.206121:0:14684:0:(cl_page.c:181:cl_page_alloc()) kmalloced 'page' : 448 at ffff881902655800. 00000020:00000001:25.0:1471329003.206129:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered 00000020:00000001:25.0:1471329003.206134:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving 00020000:00000001:25.0:1471329003.206141:0:14684:0:(lov_page.c:83:lov_page_init_raid0()) Process entered 00000020:00000001:25.0:1471329003.206148:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered 00000020:00000001:25.0:1471329003.206152:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving 00020000:00000001:25.0:1471329003.206157:0:14684:0:(lov_io.c:212:lov_sub_get()) Process entered 00020000:00000001:25.0:1471329003.206163:0:14684:0:(lov_io.c:223:lov_sub_get()) Process leaving (rc=18446612239660200384 : -131834049351232 : ffff8818fe51b1c0) 00020000:00000001:25.0:1471329003.206173:0:14684:0:(lovsub_page.c:68:lovsub_page_init()) Process entered 00000020:00000001:25.0:1471329003.206179:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered 00000020:00000001:25.0:1471329003.206184:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving 00020000:00000001:25.0:1471329003.206189:0:14684:0:(lovsub_page.c:71:lovsub_page_init()) Process leaving (rc=0 : 0 : 0) 00000008:00000001:25.0:1471329003.206199:0:14684:0:(osc_cache.c:2272:osc_prep_async_page()) Process entered 00000008:00000040:25.0:1471329003.206208:0:14684:0:(osc_cache.c:2293:osc_prep_async_page()) oap ffff881902655928 page ffffea0066a8dc00 obj off 0 00000008:00000001:25.0:1471329003.206216:0:14684:0:(osc_cache.c:2294:osc_prep_async_page()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:25.0:1471329003.206224:0:14684:0:(cl_page.c:1084:cl_page_slice_add()) Process entered 00000020:00000001:25.0:1471329003.206229:0:14684:0:(cl_page.c:1090:cl_page_slice_add()) Process leaving 00000008:00000001:25.0:1471329003.206235:0:14684:0:(osc_page.c:765:osc_lru_alloc()) Process entered 00000008:00000001:25.0:1471329003.206267:0:14684:0:(osc_page.c:799:osc_lru_alloc()) Process leaving (rc=0 : 0 : 0) 00020000:00000001:25.0:1471329003.206277:0:14684:0:(lov_page.c:110:lov_page_init_raid0()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:25.0:1471329003.206284:0:14684:0:(cl_page.c:217:cl_page_alloc()) Process leaving (rc=18446612239728596992 : -131833980954624 : ffff881902655800) 00000020:00000001:25.0:1471329003.206293:0:14684:0:(cl_page.c:272:cl_page_find()) Process leaving (rc=18446612239728596992 : -131833980954624 : ffff881902655800) The ref is set to 1 after allocation and bumped up by vvp_page_init() during init. Then cl_page_assume() is called by ll_readpage() to set the owner: 00000020:00000001:25.0:1471329003.206302:0:14684:0:(cl_page.c:657:cl_page_assume()) Process entered 00000020:00000001:25.0:1471329003.206308:0:14684:0:(cl_io.c:1130:cl_io_top()) Process entered 00000020:00000001:25.0:1471329003.206313:0:14684:0:(cl_io.c:1133:cl_io_top()) Process leaving (rc=18446612239827533920 : -131833882017696 : ffff8819084b0060) 00000020:00000001:25.0:1471329003.206321:0:14684:0:(cl_page.c:501:cl_page_invoid()) Process entered 00000020:00000001:25.0:1471329003.206327:0:14684:0:(cl_page.c:505:cl_page_invoid()) Process leaving 00000020:00000001:25.0:1471329003.206332:0:14684:0:(cl_io.c:1130:cl_io_top()) Process entered 00000020:00000001:25.0:1471329003.206337:0:14684:0:(cl_io.c:1133:cl_io_top()) Process leaving (rc=18446612239827533920 : -131833882017696 : ffff8819084b0060) 00000020:00000001:25.0:1471329003.206345:0:14684:0:(cl_page.c:521:cl_page_owner_set()) Process entered 00000020:00000001:25.0:1471329003.206357:0:14684:0:(cl_page.c:524:cl_page_owner_set()) Process leaving 00000020:00000001:25.0:1471329003.206363:0:14684:0:(cl_page.c:328:cl_page_state_set0()) Process entered 00000020:00000001:25.0:1471329003.206376:0:14684:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[2 ffff8800b214f9d0 0 1 ffff8819084b0060] 00000020:00000001:25.0:1471329003.206383:0:14684:0:(cl_page.c:331:cl_page_state_set0()) 0 -> 1 00000020:00000001:25.0:1471329003.206389:0:14684:0:(cl_page.c:338:cl_page_state_set0()) Process leaving 00000020:00000001:25.0:1471329003.206395:0:14684:0:(cl_page.c:665:cl_page_assume()) Process leaving Now the cl_page has a ref of 2, with a CPS_OWNED state and CPT_CACHEABLE type. The ref got up again in ll_readpage->ll_io_read_page->cl_2quque_add->cl_page_list_add, the ref becomes 3. Later the cl_page_prep() is called by osc_io_submit() 00000020:00000001:25.0:1471329003.206731:0:14684:0:(cl_io.c:680:cl_io_submit_rw()) Process entered 00000008:00400020:25.0:1471329003.206759:0:14684:0:(osc_io.c:146:osc_io_submit()) 1 0 00000080:00000001:25.0:1471329003.206775:0:14684:0:(vvp_page.c:207:vvp_page_prep_read()) Process entered 00000080:00000001:25.0:1471329003.206800:0:14684:0:(vvp_page.c:209:vvp_page_prep_read()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:25.0:1471329003.206808:0:14684:0:(cl_page.c:493:cl_page_invoke()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:25.0:1471329003.206815:0:14684:0:(cl_page.c:853:cl_page_io_start()) Process entered 00000020:00000001:25.0:1471329003.206821:0:14684:0:(cl_page.c:510:cl_page_owner_clear()) Process entered 00000020:00000001:25.0:1471329003.206826:0:14684:0:(cl_page.c:516:cl_page_owner_clear()) Process leaving 00000020:00000001:25.0:1471329003.206831:0:14684:0:(cl_page.c:843:cl_req_type_state()) Process entered 00000020:00000001:25.0:1471329003.206836:0:14684:0:(cl_page.c:844:cl_req_type_state()) Process leaving (rc=3 : 3 : 3) 00000020:00000001:25.0:1471329003.206844:0:14684:0:(cl_page.c:328:cl_page_state_set0()) Process entered 00000020:00000001:25.0:1471329003.206857:0:14684:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[3 ffff8800b214f9d0 1 1 ( null )] 00000020:00000001:25.0:1471329003.206864:0:14684:0:(cl_page.c:331:cl_page_state_set0()) 1 -> 3 00000020:00000001:25.0:1471329003.206870:0:14684:0:(cl_page.c:338:cl_page_state_set0()) Process leaving 00000020:00000001:25.0:1471329003.206875:0:14684:0:(cl_page.c:856:cl_page_io_start()) Process leaving 00000020:00000001:25.0:1471329003.206886:0:14684:0:(cl_page.c:889:cl_page_prep()) page@ffff881902655800[3 ffff8800b214f9d0 3 1 ( null )] 00000020:00000001:25.0:1471329003.206893:0:14684:0:(cl_page.c:889:cl_page_prep()) 0 0 The owner is cleared, and the state changed from CPS_OWNED to CPS_PAGEIN Then there is a get on the page in osc_page_submit and put on the page by cl_page_list_del as page->cp_sync_io is NULL 00000020:00000001:25.0:1471329003.206902:0:14684:0:(cl_page.c:357:cl_page_get()) Process entered 00000020:00000001:25.0:1471329003.206906:0:14684:0:(cl_page.c:359:cl_page_get()) Process leaving 00000020:00000001:25.0:1471329003.206913:0:14684:0:(cl_page.c:826:cl_page_is_vmlocked()) Process entered 00000020:00000001:25.0:1471329003.206919:0:14684:0:(cl_page.c:837:cl_page_is_vmlocked()) Process leaving (rc=1 : 1 : 1) 00000020:00000001:25.0:1471329003.206926:0:14684:0:(cl_io.c:892:cl_page_list_del()) Process entered 00000020:00000001:25.0:1471329003.206931:0:14684:0:(cl_page.c:374:cl_page_put()) Process entered 00000020:00000001:25.0:1471329003.206941:0:14684:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[4 ffff8800b214f9d0 3 1 ( null )] 00000020:00000001:25.0:1471329003.206947:0:14684:0:(cl_page.c:376:cl_page_put()) 4 00000020:00000001:25.0:1471329003.206952:0:14684:0:(cl_page.c:391:cl_page_put()) Process leaving 00000020:00000001:25.0:1471329003.206957:0:14684:0:(cl_io.c:897:cl_page_list_del()) Process leaving And a put when we return to ll_readpage, now the ref is 2 00000080:00000001:25.0:1471329003.207246:0:14684:0:(rw.c:1136:ll_io_read_page()) Process leaving (rc=0 : 0 : 0) 00000020:00000001:25.0:1471329003.207253:0:14684:0:(cl_page.c:374:cl_page_put()) Process entered 00000020:00000001:25.0:1471329003.207266:0:14684:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[3 ffff8800b214f9d0 3 1 ( null )] 00000020:00000001:25.0:1471329003.207273:0:14684:0:(cl_page.c:376:cl_page_put()) 3 00000020:00000001:25.0:1471329003.207279:0:14684:0:(cl_page.c:391:cl_page_put()) Process leaving 00000080:00000001:25.0:1471329003.207284:0:14684:0:(rw.c:1223:ll_readpage()) Process leaving (rc=0 : 0 : 0) After this the thread is waiting in filemap_fault. Now the ptlrpcd thread, when the io is done, osc_completion is called, first it calls cl_page_completion and then cl_put_page 00000008:00000001:25.0:1471329003.210591:0:2904:0:(osc_cache.c:1318:osc_completion()) Process entered 00000020:00000001:25.0:1471329003.210597:0:2904:0:(cl_page.c:843:cl_req_type_state()) Process entered 00000020:00000001:25.0:1471329003.210613:0:2904:0:(cl_page.c:844:cl_req_type_state()) Process leaving (rc=3 : 3 : 3) 00000020:00000001:25.0:1471329003.210621:0:2904:0:(cl_page.c:917:cl_page_completion()) Process entered 00000020:00000001:25.0:1471329003.210632:0:2904:0:(cl_page.c:918:cl_page_completion()) page@ffff881902655800[2 ffff8800b214f9d0 3 1 ( null )] 00000020:00000001:25.0:1471329003.210638:0:2904:0:(cl_page.c:918:cl_page_completion()) 0 0 00000020:00000001:25.0:1471329003.210645:0:2904:0:(cl_page.c:328:cl_page_state_set0()) Process entered 00000020:00000001:25.0:1471329003.210656:0:2904:0:(cl_page.c:331:cl_page_state_set0()) page@ffff881902655800[2 ffff8800b214f9d0 3 1 ( null )] 00000020:00000001:25.0:1471329003.210661:0:2904:0:(cl_page.c:331:cl_page_state_set0()) 3 -> 0 00000020:00000001:25.0:1471329003.210667:0:2904:0:(cl_page.c:338:cl_page_state_set0()) Process leaving 00000080:00000001:25.0:1471329003.210687:0:2904:0:(vvp_page.c:262:vvp_page_completion_read()) Process entered 00000080:00008000:25.0:1471329003.210699:0:2904:0:(vvp_page.c:265:vvp_page_completion_read()) page@ffff881902655800[2 ffff8800b214f9d0 0 1 ( null )] 00000080:00008000:25.0:1471329003.210705:0:2904:0:(vvp_page.c:265:vvp_page_completion_read()) completing READ with 0 00000080:00000001:25.0:1471329003.210852:0:2904:0:(vvp_page.c:280:vvp_page_completion_read()) Process leaving 00000020:00000001:25.0:1471329003.210859:0:2904:0:(cl_page.c:930:cl_page_completion()) Process leaving 00000020:00000001:25.0:1471329003.210866:0:2904:0:(cl_page.c:374:cl_page_put()) Process entered 00000020:00000001:25.0:1471329003.210887:0:2904:0:(cl_page.c:376:cl_page_put()) page@ffff881902655800[2 ffff8800b214f9d0 0 1 ( null )] 00000020:00000001:25.0:1471329003.210894:0:2904:0:(cl_page.c:376:cl_page_put()) 2 00000020:00000001:25.0:1471329003.210900:0:2904:0:(cl_page.c:391:cl_page_put()) Process leaving 00000008:00000001:25.0:1471329003.210905:0:2904:0:(osc_cache.c:1356:osc_completion()) Process leaving (rc=0 : 0 : 0) The state is set to CPS_CACHED, then the page is exported to vm, finally the ref is dropped to 1. Now if osc_lru_shrink kicks in, lru_page_busy will fail the check. If an extra cl_page ref could be taken during page fault, it can also fix the problem. However I don't see where is the best place to do this. Thanks

            People

              jay Jinshan Xiong (Inactive)
              lidongyang Li Dongyang (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: