[mpich-discuss] MPE profiling question
Yusong Wang - NOAA Affiliate
yusong.wang at noaa.gov
Fri Feb 22 10:18:17 CST 2013
Hi,
I am trying to use MPE to do a profiling for all the MPI statements in
a complex Fortran code with MPICH2-1.4.1 on 1008 cores . The code was
compiled with
... MPICH2-1.4.1/bin/mpif90 -mpe=mpilog ...
While during converting from clog to slog file with the clog2TOslog2
command, millions of lines like below appeared on the screen and it
was out of some time limit eventually. It looks like some events
should not be recorded. This also leads to extreme slowness and
generated a 177GB profile for the code to be studied. What is the
possible cause of this? How to solve the problem?
Some clog2print output can be found at the end.
State{ Primitive[ infobox[
TimeBBox(30.777848601341248,30.777848601341248) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.77785, 588) (30.77785,
588) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.777848601341248,30.777848601341248) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.77785, 588) (30.77785,
588) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[ TimeBBox(30.7866690158844,30.7866690158844)
Category=ObjDef{ evts=(210,211), Category[ index=106,
name=UnknownType-106, topo=State, color=(153,204,255,255,true),
isUsed=true, width=1, vis=true, search=true, ratios=0.0,0.0, count=0 ]
}: ] (30.786669, 490) (30.786669, 490) ] bsize=32 }
State{ Primitive[ infobox[ TimeBBox(30.7866690158844,30.7866690158844)
Category=ObjDef{ evts=(210,211), Category[ index=106,
name=UnknownType-106, topo=State, color=(153,204,255,255,true),
isUsed=true, width=1, vis=true, search=true, ratios=0.0,0.0, count=0 ]
}: ] (30.786669, 490) (30.786669, 490) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.78674340248108,30.78674340248108) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786743, 492)
(30.786743, 492) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.78674340248108,30.78674340248108) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786743, 492)
(30.786743, 492) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.786930561065674,30.786930561065674) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.78693, 482) (30.78693,
482) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.786930561065674,30.786930561065674) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.78693, 482) (30.78693,
482) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.78696846961975,30.78696846961975) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786968, 481)
(30.786968, 481) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.78696846961975,30.78696846961975) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786968, 481)
(30.786968, 481) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.777848601341248,30.777848601341248) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.77785, 588) (30.77785,
588) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.777848601341248,30.777848601341248) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.77785, 588) (30.77785,
588) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[ TimeBBox(30.7866690158844,30.7866690158844)
Category=ObjDef{ evts=(210,211), Category[ index=106,
name=UnknownType-106, topo=State, color=(153,204,255,255,true),
isUsed=true, width=1, vis=true, search=true, ratios=0.0,0.0, count=0 ]
}: ] (30.786669, 490) (30.786669, 490) ] bsize=32 }
State{ Primitive[ infobox[ TimeBBox(30.7866690158844,30.7866690158844)
Category=ObjDef{ evts=(210,211), Category[ index=106,
name=UnknownType-106, topo=State, color=(153,204,255,255,true),
isUsed=true, width=1, vis=true, search=true, ratios=0.0,0.0, count=0 ]
}: ] (30.786669, 490) (30.786669, 490) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.78674340248108,30.78674340248108) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786743, 492)
(30.786743, 492) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.78674340248108,30.78674340248108) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.786743, 492)
(30.786743, 492) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
State{ Primitive[ infobox[
TimeBBox(30.786930561065674,30.786930561065674) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.78693, 482) (30.78693,
482) ] bsize=32 }
State{ Primitive[ infobox[
TimeBBox(30.786930561065674,30.786930561065674) Category=ObjDef{
evts=(210,211), Category[ index=106, name=UnknownType-106, topo=State,
color=(153,204,255,255,true), isUsed=true, width=1, vis=true,
search=true, ratios=0.0,0.0, count=0 ] }: ] (30.78693, 482) (30.78693,
482) ] bsize=32 }
Drawable.Order: WARNING! Equal Drawables?
Some outputs from clog2print
fe7>clog2print NEMS.x.clog2 | more
GUI_LIBDIR is set. GUI_LIBDIR = /home/Yusong.Wang/Tools/MPE2/lib
CLOG-02.44
is_big_endian=true
is_finalzed=true
block_size=65536
num_buffered_blocks=128
max_comm_world_size=1008
max_thread_count=1
known_eventID_start=0
user_eventID_start=600
known_solo_eventID_start=-10
user_solo_eventID_start=5000
known_stateID_count=300
user_stateID_count=0
known_solo_eventID_count=2
user_solo_eventID_count=0
commtable_fptr=189927785472
RecHeader[ time=-0.0014635324478149414, icomm=0, rank=286, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.0014914274215698242 ]
RecHeader[ time=-0.0014625787734985352, icomm=0, rank=286, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=286, wrank=286,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014625787734985352, icomm=0, rank=286, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=315, rank=0, wrank=286,
gcomm=1187486374-1.36148902997195E9-r36i1n3
RecHeader[ time=-0.001454472541809082, icomm=0, rank=278, thread=0, rectype=11 ]
RecTshift[ timeshift=0.0014923810958862305 ]
RecHeader[ time=-0.0014532804489135742, icomm=0, rank=278, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=278, wrank=278,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014532804489135742, icomm=0, rank=278, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=307, rank=0, wrank=278,
gcomm=1259602162-1.361489029971928E9-r36i1n3
RecHeader[ time=-0.0014530420303344727, icomm=0, rank=283, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490950584411621 ]
RecHeader[ time=-0.001452803611755371, icomm=0, rank=279, thread=0, rectype=11 ]
RecTshift[ timeshift=0.0014919042587280273 ]
RecHeader[ time=-0.0014520883560180664, icomm=0, rank=283, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=283, wrank=283,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014520883560180664, icomm=0, rank=283, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=312, rank=0, wrank=283,
gcomm=2019836162-1.361489029971952E9-r36i1n3
RecHeader[ time=-0.0014518499374389648, icomm=0, rank=279, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=279, wrank=279,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014518499374389648, icomm=0, rank=279, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=308, rank=0, wrank=279,
gcomm=982152232-1.361489029971961E9-r36i1n3
RecHeader[ time=-0.0014477968215942383, icomm=0, rank=276, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.0014928579330444336 ]
RecHeader[ time=-0.0014477968215942383, icomm=0, rank=276, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=276, wrank=276,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014477968215942383, icomm=0, rank=276, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=305, rank=0, wrank=276,
gcomm=1814502021-1.361489029971937E9-r36i1n3
RecHeader[ time=-0.001446366310119629, icomm=0, rank=277, thread=0, rectype=11 ]
RecTshift[ timeshift=0.0014933347702026367 ]
RecHeader[ time=-0.0014454126358032227, icomm=0, rank=277, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=277, wrank=277,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014454126358032227, icomm=0, rank=277, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=306, rank=0, wrank=277,
gcomm=1537052091-1.361489029971946E9-r36i1n3
RecHeader[ time=-0.0014358758926391602, icomm=0, rank=287, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490950584411621 ]
RecHeader[ time=-0.001434922218322754, icomm=0, rank=287, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=287, wrank=287,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.001434922218322754, icomm=0, rank=287, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=316, rank=0, wrank=287,
gcomm=910036444-1.361489029971966E9-r36i1n3
RecHeader[ time=-0.0014303922653198242, icomm=0, rank=285, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.0014914274215698242 ]
RecHeader[ time=-0.0014303922653198242, icomm=0, rank=285, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=285, wrank=285,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014303922653198242, icomm=0, rank=285, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=314, rank=0, wrank=285,
gcomm=1464936303-1.361489029971933E9-r36i1n3
RecHeader[ time=-0.0014175176620483398, icomm=0, rank=282, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490473747253418 ]
RecHeader[ time=-0.0014165639877319336, icomm=0, rank=282, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=282, wrank=282,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014165639877319336, icomm=0, rank=282, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=311, rank=0, wrank=282,
gcomm=149802444-1.361489029971928E9-r36i1n3
RecHeader[ time=-0.0014106035232543945, icomm=0, rank=281, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490473747253418 ]
RecHeader[ time=-0.0014106035232543945, icomm=0, rank=281, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=281, wrank=281,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0014106035232543945, icomm=0, rank=281, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=310, rank=0, wrank=281,
gcomm=427252373-1.361489029971947E9-r36i1n3
RecHeader[ time=-0.0013779401779174805, icomm=0, rank=284, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490950584411621 ]
RecHeader[ time=-0.0013769865036010742, icomm=0, rank=284, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=284, wrank=284,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0013769865036010742, icomm=0, rank=284, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=313, rank=0, wrank=284,
gcomm=1742386233-1.361489029971935E9-r36i1n3
RecHeader[ time=-0.0013734102249145508, icomm=0, rank=280, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001490473747253418 ]
RecHeader[ time=-0.0013724565505981445, icomm=0, rank=280, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=280, wrank=280,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0013715028762817383, icomm=0, rank=280, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=309, rank=0, wrank=280,
gcomm=704702303-1.361489029971955E9-r36i1n3
RecHeader[ time=-0.0012382268905639648, icomm=0, rank=380, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001263260841369629 ]
RecHeader[ time=-0.0012382268905639648, icomm=0, rank=380, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=380, wrank=380,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0012382268905639648, icomm=0, rank=380, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=409, rank=0, wrank=380,
gcomm=646419710-1.361489029982929E9-r36i1n11
RecHeader[ time=-0.001236557960510254, icomm=0, rank=381, thread=0, rectype=11 ]
RecTshift[ timeshift=0.001263737678527832 ]
RecHeader[ time=-0.001236557960510254, icomm=0, rank=381, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=381, wrank=381,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0012356042861938477, icomm=0, rank=381, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=410, rank=0, wrank=381,
gcomm=368969781-1.361489029982935E9-r36i1n11
RecHeader[ time=-0.001231074333190918, icomm=0, rank=379, thread=0, rectype=11 ]
RecTshift[ timeshift=0.0012642145156860352 ]
RecHeader[ time=-0.0012301206588745117, icomm=0, rank=379, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=379, wrank=379,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0012301206588745117, icomm=0, rank=379, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=408, rank=0, wrank=379,
gcomm=923869640-1.361489029982941E9-r36i1n11
RecHeader[ time=-0.001221776008605957, icomm=0, rank=376, thread=0, rectype=11 ]
RecTshift[ timeshift=0.0012627840042114258 ]
RecHeader[ time=-0.001221776008605957, icomm=0, rank=376, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=376, wrank=376,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.001221776008605957, icomm=0, rank=376, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=405, rank=0, wrank=376,
gcomm=1756219428-1.361489029982958E9-r36i1n11
RecHeader[ time=-0.0012112855911254883, icomm=0, rank=373, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.0012623071670532227 ]
RecHeader[ time=-0.001210331916809082, icomm=0, rank=373, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=373, wrank=373,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.001210331916809082, icomm=0, rank=373, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=402, rank=0, wrank=373,
gcomm=441085569-1.361489029982914E9-r36i1n11
RecHeader[ time=-0.0012046098709106445, icomm=0, rank=383, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.0012627840042114258 ]
RecHeader[ time=-0.0012036561965942383, icomm=0, rank=383, thread=0, rectype=9 ]
RecComm[ etype=CommWorldCreate, icomm=0, rank=383, wrank=383,
gcomm=369972154-1.361489029949814E9-r6i2n0
RecHeader[ time=-0.0012036561965942383, icomm=0, rank=383, thread=0, rectype=9 ]
RecComm[ etype=CommSelfCreate, icomm=412, rank=0, wrank=383,
gcomm=1961553570-1.361489029982915E9-r36i1n11
RecHeader[ time=-0.0011996030807495117, icomm=0, rank=382, thread=0,
rectype=11 ]
RecTshift[ timeshift=0.001261591911315918 ]
Thanks,
Yusong
More information about the discuss
mailing list