search

renzhengeek / issues

0 stars 0 forks source link

time analysis #27

Closed renzhengeek closed 8 years ago

renzhengeek commented 8 years ago 
n1:~/951724 # ./iomaker -w -v -l -1 /mnt/shared/file 1000
buffer length/nCount = 1024 1000
   1| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:142 msecs
   2| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   3| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   4| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   5| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   6| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   7| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
   8| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
   9| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  10| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:19 msecs
  11| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:17 msecs
  12| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  13| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  14| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  15| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  16| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  17| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  18| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  19| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  20| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  21| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  22| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  23| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  24| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  25| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  26| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  27| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14 msecs
  28| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  29| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  30| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  31| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:13 msecs
  32| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14155 msecs
  33| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:21020 msecs
  34| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:14608 msecs
  35| 1 2 3 4 5 6 7 8 9 10 ...1000 write time:23411 msecs
Nov 11 18:38:07 n1 kernel: [  481.970383] ocfs2_inode_lock_full_nested<-- 11 ms
Nov 11 18:38:07 n1 kernel: [  481.970899]       __ocfs2_cluster_lock-->
Nov 11 18:38:07 n1 kernel: [  481.970901] __ocfs2_cluster_lock<--
Nov 11 18:38:07 n1 kernel: [  481.970902] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:07 n1 kernel: [  481.970904]       __ocfs2_cluster_lock-->
Nov 11 18:38:07 n1 kernel: [  481.970905] __ocfs2_cluster_lock<--
Nov 11 18:38:07 n1 kernel: [  481.970906] ocfs2_inode_lock_full_nested<-- 0 ms
Nov 11 18:38:07 n1 kernel: [  481.970908] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:07 n1 mgmtd: [3301]: debug: [mgmtd] stopped
Nov 11 18:38:07 n1 kernel: [  481.970910]       __ocfs2_cluster_lock-->
Nov 11 18:38:07 n1 kernel: [  481.970911]       OCFS2_LOCK_BLOCKED:level(5) ? lockres->l_level(5)
Nov 11 18:38:07 n1 kernel: [  481.983505] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:07 n1 kernel: [  481.983507] (iomaker,4262,1):__ocfs2_cluster_lock:1472 ERROR: lockres M0000000000000000011a1800000000, convert from 3 to 5
Nov 11 18:38:07 n1 kernel: [  481.983519] (iomaker,4262,1):__ocfs2_cluster_lock:1493 ERROR: lock M0000000000000000011a1800000000, successful return from ocfs2_dlm_lock
Nov 11 18:38:07 n1 kernel: [  481.983521]       OCFS2_LOCK_BUSY: level(5) > lockres->l_level(3)
Nov 11 18:38:07 n1 kernel: [  481.983931] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:07 n1 kernel: [  481.983933]       OCFS2_LOCK_UPCONVERT_FINISHING: level(5):->l_level(5)
Nov 11 18:38:07 n1 kernel: [  481.983934] __ocfs2_cluster_lock<--
Nov 11 18:38:07 n1 kernel: [  481.983937] ocfs2_inode_lock_full_nested<-- 13 ms
Nov 11 18:38:08 n1 kernel: [  481.983969]       __ocfs2_cluster_lock-->
Nov 11 18:38:08 n1 kernel: [  481.983971] __ocfs2_cluster_lock<--
Nov 11 18:38:08 n1 kernel: [  481.983972] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:08 n1 kernel: [  481.983973]       __ocfs2_cluster_lock-->
Nov 11 18:38:08 n1 kernel: [  481.983974] __ocfs2_cluster_lock<--
Nov 11 18:38:08 n1 kernel: [  481.983975] ocfs2_inode_lock_full_nested<-- 0 ms
Nov 11 18:38:08 n1 kernel: [  481.983978] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:08 n1 kernel: [  481.983979]       __ocfs2_cluster_lock-->
Nov 11 18:38:08 n1 kernel: [  481.983980]       OCFS2_LOCK_BLOCKED:level(5) ? lockres->l_level(5)
Nov 11 18:38:08 n1 kernel: [  481.993996] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:09 n1 kernel: [  481.993999] (iomaker,4262,1):__ocfs2_cluster_lock:1472 ERROR: lockres M0000000000000000011a1800000000, convert from 3 to 5
Nov 11 18:38:09 n1 kernel: [  481.994010] (iomaker,4262,1):__ocfs2_cluster_lock:1493 ERROR: lock M0000000000000000011a1800000000, successful return from ocfs2_dlm_lock
Nov 11 18:38:09 n1 kernel: [  481.994012]       OCFS2_LOCK_BUSY: level(5) > lockres->l_level(3)
Nov 11 18:38:09 n1 kernel: [  481.994361] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:09 n1 kernel: [  481.994363]       OCFS2_LOCK_UPCONVERT_FINISHING: level(5):->l_level(5)
Nov 11 18:38:09 n1 kernel: [  481.994364] __ocfs2_cluster_lock<--
Nov 11 18:38:09 n1 kernel: [  481.994367] ocfs2_inode_lock_full_nested<-- 10 ms
Nov 11 18:38:09 n1 kernel: [  481.994398]       __ocfs2_cluster_lock-->
Nov 11 18:38:09 n1 kernel: [  481.994400] __ocfs2_cluster_lock<--
Nov 11 18:38:09 n1 kernel: [  481.994401] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:09 n1 kernel: [  481.994402]       __ocfs2_cluster_lock-->
Nov 11 18:38:09 n1 kernel: [  481.994403] __ocfs2_cluster_lock<--
Nov 11 18:38:09 n1 kernel: [  481.994404] ocfs2_inode_lock_full_nested<-- 0 ms
Nov 11 18:38:09 n1 kernel: [  481.994407] ocfs2_inode_lock_full_nested-->
Nov 11 18:38:09 n1 kernel: [  481.994408]       __ocfs2_cluster_lock-->
Nov 11 18:38:09 n1 kernel: [  481.994409]       OCFS2_LOCK_BLOCKED:level(5) ? lockres->l_level(5)
Nov 11 18:38:09 n1 kernel: [  482.005993] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:09 n1 kernel: [  482.005996] (iomaker,4262,1):__ocfs2_cluster_lock:1472 ERROR: lockres M0000000000000000011a1800000000, convert from 3 to 5
Nov 11 18:38:09 n1 kernel: [  482.006007] (iomaker,4262,1):__ocfs2_cluster_lock:1493 ERROR: lock M0000000000000000011a1800000000, successful return from ocfs2_dlm_lock
Nov 11 18:38:09 n1 kernel: [  482.006009]       OCFS2_LOCK_BUSY: level(5) > lockres->l_level(3)
Nov 11 18:38:09 n1 kernel: [  482.006415] (iomaker,4262,1):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:38:09 n1 kernel: [  482.006417]       OCFS2_LOCK_UPCONVERT_FINISHING: level(5):->l_level(5)
Nov 11 18:38:09 n1 kernel: [  482.006419] __ocfs2_cluster_lock<--
Nov 11 18:38:09 n1 kernel: [  482.006421] ocfs2_inode_lock_full_nested<-- 13 ms
renzhengeek commented 8 years ago 
Total time: 0 msecs
n2:~/951724 # ./iomaker -v -l -1 /mnt/shared/file 1000   
buffer length/nCount = 1024 1000
   1| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:20357 msec
   2| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:3302 msec
   3| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:13 msec
   4| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:10049 msec
   5| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:4575 msec
   6| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:13 msec
   7| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
   8| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
   9| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  10| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  11| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  12| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  13| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  14| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  15| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:8 msec
  16| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  17| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:15 msec
  18| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:10 msec
  19| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:17 msec
  20| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:15 msec
  21| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:10 msec
  22| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  23| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  24| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  25| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  26| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  27| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  28| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  29| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  30| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  31| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  32| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  33| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  34| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  35| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  36| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  37| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  38| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  39| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  40| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:9 msec
  41| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:2470 msec
  42| 1 2 3 4 5 6 7 8 9 10 ...1000 read time:20472 msec
Nov 11 18:44:46 n2 kernel: [  248.932842] ocfs2_inode_lock_full_nested<-- 0 ms
Nov 11 18:44:46 n2 kernel: [  248.932846] ocfs2_readpage-->
Nov 11 18:44:46 n2 kernel: [  248.932847] ocfs2_inode_lock_with_page-->
Nov 11 18:44:46 n2 kernel: [  248.932848] ocfs2_inode_lock_full_nested-->
Nov 11 18:44:46 n2 kernel: [  248.932849]       __ocfs2_cluster_lock-->
Nov 11 18:44:46 n2 kernel: [  248.932850]       OCFS2_LOCK_BLOCKED:level(3) ? lockres->l_level(3)
Nov 11 18:44:46 n2 kernel: [  248.932852] (iomaker,4081,0):__ocfs2_cluster_lock:1523 ERROR: wait(1) && OCFS2_LOCK_NONBLOCK && (OCFS2_LOCK_BUSY|OCFS2_LOCK_BLOCKED)
Nov 11 18:44:46 n2 kernel: [  248.932854] __ocfs2_cluster_lock<--
Nov 11 18:44:46 n2 kernel: [  248.932855] ocfs2_inode_lock_full_nested<-- 0 ms
Nov 11 18:44:47 n2 kernel: [  248.932856] ocfs2_inode_lock_full_nested-->
Nov 11 18:44:47 n2 kernel: [  248.932857]       __ocfs2_cluster_lock-->
Nov 11 18:44:47 n2 kernel: [  248.932858]       OCFS2_LOCK_BLOCKED:level(3) ? lockres->l_level(3)
Nov 11 18:44:47 n2 kernel: [  248.932907] (iomaker,4081,0):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:44:47 n2 kernel: [  248.932909] (iomaker,4081,0):__ocfs2_cluster_lock:1472 ERROR: lockres M0000000000000000011a1800000000, convert from 0 to 3
Nov 11 18:44:47 n2 kernel: [  248.932922] (iomaker,4081,0):__ocfs2_cluster_lock:1493 ERROR: lock M0000000000000000011a1800000000, successful return from ocfs2_dlm_lock
Nov 11 18:44:47 n2 kernel: [  248.932925]       OCFS2_LOCK_BUSY: level(3) > lockres->l_level(0)
Nov 11 18:44:47 n2 kernel: [  248.945168] (iomaker,4081,0):__ocfs2_cluster_lock:1532 ERROR: ocfs2_wait_for_mask ret=0
Nov 11 18:44:47 n2 kernel: [  248.945170]       OCFS2_LOCK_UPCONVERT_FINISHING: level(3):->l_level(3)
Nov 11 18:44:47 n2 kernel: [  248.945172] __ocfs2_cluster_lock<--
Nov 11 18:44:47 n2 kernel: [  248.945175] ocfs2_inode_lock_full_nested<-- 12 ms
Nov 11 18:44:47 n2 kernel: [  248.945178] ocfs2_inode_lock_with_page<-- 12 ms
Nov 11 18:44:47 n2 kernel: [  248.945179] ocfs2_readpage <-- 12 ms