|
»
Performance Issue Feedback (Pablo's problem)
|
View:
New views
5 Messages
—
Rating Filter:
Alert me
|
 |
Performance Issue Feedback (Pablo's problem)
by Tony Wilson-3
::
Rate this Message:
Thanks to being up at ungodly hours for cricket (SA vs Australia), I have had time on my hands to play around with Pablo's performance problem with loading huge files. I had originally planned on putting out large boring tables of figures, but after GITing the pre-release 5.1.4, I believe that I have a good handle on the main issues so will summarize. Done on XP2 2.4GHz Celeron with 1Gb, I/O to Raid pair (double normal bandwidth), Linux is Gutsy Ubuntu in 676Mb Sun xVM VirtualBox. All tests done with 'nogc' and sufficient memory preallocated. 1. There is a consult I/O performance issue in 5.1.3 MinGW/Cygwin - IT IS FIXED FOR MINGW BY CURRENT PRE-RELEASE 5.1.4 Created file of a 20mb one line comment (%) and ':- statistics,halt.'. Isolates I/O and should have little Yap overhead. MinGW 5.1.3 MinGW 5.1.4 Cygwin 5.1.3 Cygwin 5.1.4 4.406 sec. cputime 0.578 sec. cputime 7.594 sec. cputime 7.516 sec. cputime 11.250 sec. systime 0.031 sec. systime 0.125 sec. systime 0.110 sec. systime 16.875 sec. elapsed 0.625 sec. elapsed 8.109 sec. elapsed 8.166 sec. elapsed Virtual Disk Shared directory NTFS Linux 5.1.3 Linux 5.1.4 Linux 5.1.3 Linux 5.1.4 1.120 sec. cputime 1.060 sec. cputime 0.172 sec. runtime 0.156 sec. cputime 0.084 sec. systime 0.080 sec. systime 3.104 sec. systime 3.012 sec. systime 1.210 sec. elapsed 1.152 sec. elapsed 5.427 sec. elapsed 4.755 sec. elapsed Note: I added 'systime' using stime/KernelTime to clarify elapsed/cpu difference. (Git mbox patch attached) Shared NTFS elapsed includes unaccounted Windows time 2. The Cygwin builds all do not restore 'startup'. 'startup' appears to be built in make but is only circa 2kb after save(startup). As a result, every time Cygwin Yap starts, it loads pl/boot.yap, adding 0.3-0.4s. Verified that dcc.fc.up.pt tar.gz has small file. 3. The silent load (-L) problem reported by me is also fixed in 5.1.4 WITH THE PATCH REMOVED. I suspect that whatever fixed the MinGW performance, also fixed this. 4. I discovered a disparity in tail recursion optimization. All versions and flavours. '_repeat2'( _). '_repeat2'( N) :- N > 1, N2 is N - 1, '_repeat2'( N2). repeat2( N) :- N > 0, '_repeat2'( N). '_for2'( I, I, _). '_for2'( I, C, L) :- C < L, C2 is C + 1, '_for2'( I, C2, L). for2( A, B, C) :- B =< C, '_for2'( A, B, C). for2(_,1,2000000),fail;statistics repeat2(2000000),fail;statistics global stack: 4632 in use, 4876 max global stack: 4584 in use, 8004588 max 5. Discovered a bug in 5.1.4 which is probably the most amusing one I've ever found and would probably never affect anyone. Not on 5.1.3 and affects all flavours of 5.1.4. 20Mb single line comment file+statistics 20Mb 2000000 line comment file+statistics global stack: 4556 in use, 4704 max global stack: 48004532 in use, 48004544 max Note: Cygwin 5.1.4 program took 3x as long as MinGW 5.1.4 to create files. If stack not preallocated -> YAP ERROR: Global Collided against Local (00680000--0065FD74) Anybody want to employ me as a software destroyer? ;-) Regards, Tony Wilson Durban, South Africa PS Don't worry Vitor, people don't bother finding bugs in software they don't like. >From 14713dafa8a3d4cc3de1138f8219380ad3bb012a Mon Sep 17 00:00:00 2001 From: Tony Wilson <soduktile@...> Date: Sun, 18 Jan 2009 04:58:25 +0200 Subject: [PATCH] Add systime (stime/KernelTime) to statistics/0 Caveats: systime/walltime inconsistency visible on small times (yap -g statistics,halt) not serious as cputime/walltime inconsistency pre-existed systime is not correct for threads single StartOfTimes_sys and last_time_sys only tested on Linux (Ubuntu), Cygwin and MinGW (under Cygwin not MSYS) diff --git a/C/stdpreds.c b/C/stdpreds.c index b2a30c1..4bd25b8 100644 --- a/C/stdpreds.c +++ b/C/stdpreds.c @@ -333,6 +333,7 @@ STD_PROTO(static Int p_statistics_trail_info, (void)); STD_PROTO(static Term mk_argc_list, (void)); STD_PROTO(static Int p_argv, (void)); STD_PROTO(static Int p_cputime, (void)); +STD_PROTO(static Int p_systime, (void)); STD_PROTO(static Int p_runtime, (void)); STD_PROTO(static Int p_walltime, (void)); STD_PROTO(static Int p_access_yap_flags, (void)); @@ -788,6 +789,15 @@ p_cputime(void) } static Int +p_systime(void) +{ + Int now, interval; + Yap_systime_interval(&now, &interval); + return( Yap_unify_constant(ARG1, MkIntegerTerm(now)) && + Yap_unify_constant(ARG2, MkIntegerTerm(interval)) ); +} + +static Int p_walltime(void) { Int now, interval; @@ -3908,6 +3918,7 @@ Yap_InitCPreds(void) Yap_InitCPred("$argv", 1, p_argv, SafePredFlag|HiddenPredFlag); Yap_InitCPred("$runtime", 2, p_runtime, SafePredFlag|SyncPredFlag|HiddenPredFlag); Yap_InitCPred("$cputime", 2, p_cputime, SafePredFlag|SyncPredFlag|HiddenPredFlag); + Yap_InitCPred("$systime", 2, p_systime, SafePredFlag|SyncPredFlag|HiddenPredFlag); Yap_InitCPred("$walltime", 2, p_walltime, SafePredFlag|SyncPredFlag|HiddenPredFlag); Yap_InitCPred("$access_yap_flags", 2, p_access_yap_flags, SafePredFlag|HiddenPredFlag); Yap_InitCPred("$set_yap_flags", 2, p_set_yap_flags, SafePredFlag|SyncPredFlag|HiddenPredFlag); diff --git a/C/sysbits.c b/C/sysbits.c index 2def996..e0ca791 100644 --- a/C/sysbits.c +++ b/C/sysbits.c @@ -320,6 +320,8 @@ static struct timeval StartOfTimes; /* since last call to runtime */ static struct timeval last_time; #endif +static struct timeval last_time_sys; +static struct timeval StartOfTimes_sys; /* store user time in this variable */ static void @@ -334,6 +336,8 @@ InitTime (void) getrusage(RUSAGE_SELF, &rusage); last_time.tv_sec = StartOfTimes.tv_sec = rusage.ru_utime.tv_sec; last_time.tv_usec = StartOfTimes.tv_usec = rusage.ru_utime.tv_usec; + last_time_sys.tv_sec = StartOfTimes_sys.tv_sec = rusage.ru_stime.tv_sec; + last_time_sys.tv_usec = StartOfTimes_sys.tv_usec = rusage.ru_stime.tv_usec; } @@ -360,6 +364,19 @@ void Yap_cputime_interval(Int *now,Int *interval) last_time.tv_sec = rusage.ru_utime.tv_sec; } +void Yap_systime_interval(Int *now,Int *interval) +{ + struct rusage rusage; + + getrusage(RUSAGE_SELF, &rusage); + *now = (rusage.ru_stime.tv_sec - StartOfTimes_sys.tv_sec) * 1000 + + (rusage.ru_stime.tv_usec - StartOfTimes_sys.tv_usec) / 1000; + *interval = (rusage.ru_stime.tv_sec - last_time_sys.tv_sec) * 1000 + + (rusage.ru_stime.tv_usec - last_time_sys.tv_usec) / 1000; + last_time_sys.tv_usec = rusage.ru_stime.tv_usec; + last_time_sys.tv_sec = rusage.ru_stime.tv_sec; +} + #elif defined(_WIN32) #ifdef __GNUC__ @@ -389,6 +406,8 @@ void Yap_cputime_interval(Int *now,Int *interval) static FILETIME StartOfTimes, last_time; +static FILETIME StartOfTimes_sys, last_time_sys; + static clock_t TimesStartOfTimes, Times_last_time; /* store user time in this variable */ @@ -407,6 +426,10 @@ InitTime (void) last_time.dwHighDateTime = UserTime.dwHighDateTime; StartOfTimes.dwLowDateTime = UserTime.dwLowDateTime; StartOfTimes.dwHighDateTime = UserTime.dwHighDateTime; + last_time_sys.dwLowDateTime = KernelTime.dwLowDateTime; + last_time_sys.dwHighDateTime = KernelTime.dwHighDateTime; + StartOfTimes_sys.dwLowDateTime = KernelTime.dwLowDateTime; + StartOfTimes_sys.dwHighDateTime = KernelTime.dwHighDateTime; } } @@ -477,6 +500,34 @@ void Yap_cputime_interval(Int *now,Int *interval) } } +void Yap_systime_interval(Int *now,Int *interval) +{ + HANDLE hProcess = GetCurrentProcess(); + FILETIME CreationTime, ExitTime, KernelTime, UserTime; + if (!GetProcessTimes(hProcess, &CreationTime, &ExitTime, &KernelTime, &UserTime)) { + *now = *interval = 0; /* not available */ + } else { +#ifdef __GNUC__ + unsigned long long int t1 = + sub_utime(KernelTime, StartOfTimes_sys); + unsigned long long int t2 = + sub_utime(KernelTime, last_time_sys); + do_div(t1,10000); + *now = (Int)t1; + do_div(t2,10000); + *interval = (Int)t2; +#endif +#ifdef _MSC_VER + __int64 t1 = *(__int64 *)&KernelTime - *(__int64 *)&StartOfTimes_sys; + __int64 t2 = *(__int64 *)&KernelTime - *(__int64 *)&last_time_sys; + *now = (Int)(t1/10000); + *interval = (Int)(t2/10000); +#endif + last_time_sys.dwLowDateTime = KernelTime.dwLowDateTime; + last_time_sys.dwHighDateTime = KernelTime.dwHighDateTime; + } +} + #elif HAVE_TIMES #if defined(_WIN32) @@ -520,6 +571,8 @@ void Yap_cputime_interval(Int *now,Int *interval) static clock_t StartOfTimes, last_time; +static clock_t StartOfTimes_sys, last_time_sys; + /* store user time in this variable */ static void InitTime (void) @@ -527,6 +580,7 @@ InitTime (void) struct tms t; times (&t); last_time = StartOfTimes = t.tms_utime; + last_time_sys = StartOfTimes_sys = t.tms_stime; } UInt @@ -546,6 +600,15 @@ void Yap_cputime_interval(Int *now,Int *interval) last_time = t.tms_utime; } +void Yap_systime_interval(Int *now,Int *interval) +{ + struct tms t; + times (&t); + *now = ((t.tms_stime - StartOfTimes_sys)*1000) / TicksPerSec; + *interval = (t.tms_stime - last_time_sys) * 1000 / TicksPerSec; + last_time_sys = t.tms_stime; +} + #else /* HAVE_TIMES */ #ifdef SIMICS @@ -597,6 +660,11 @@ void Yap_cputime_interval(Int *now,Int *interval) last_time.tv_sec = tp.tv_sec; } +void Yap_systime_interval(Int *now,Int *interval) +{ + *now = *interval = 0; /* not available */ +} + #endif /* SIMICS */ #ifdef COMMENTED_OUT diff --git a/H/Yapproto.h b/H/Yapproto.h index be55677..ef3a955 100644 --- a/H/Yapproto.h +++ b/H/Yapproto.h @@ -313,6 +313,7 @@ void STD_PROTO(Yap_InitSysPath,(void)); void STD_PROTO(Yap_SetTextFile,(char *)); #endif void STD_PROTO(Yap_cputime_interval,(Int *,Int *)); +void STD_PROTO(Yap_systime_interval,(Int *,Int *)); void STD_PROTO(Yap_walltime_interval,(Int *,Int *)); void STD_PROTO(Yap_InitSysbits,(void)); void STD_PROTO(Yap_InitSysPreds,(void)); diff --git a/pl/statistics.yap b/pl/statistics.yap index 41df05e..02a7a5b 100644 --- a/pl/statistics.yap +++ b/pl/statistics.yap @@ -20,6 +20,7 @@ statistics :- '$runtime'(Runtime,_), '$cputime'(CPUtime,_), + '$systime'(SYStime,_), '$walltime'(Walltime,_), '$statistics_heap_info'(HpSpa, HpInUse), '$statistics_heap_max'(HpMax), @@ -33,9 +34,9 @@ statistics :- '$inform_trail_overflows'(NOfTO,TotTOTime), '$inform_gc'(NOfGC,TotGCTime,TotGCSize), '$inform_agc'(NOfAGC,TotAGCTime,TotAGCSize), - '$statistics'(Runtime,CPUtime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, TrlInUse,TrlMax,StkSpa, GlobInU, LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize). + '$statistics'(Runtime,CPUtime,SYStime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, TrlInUse,TrlMax,StkSpa, GlobInU, LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize). -'$statistics'(Runtime,CPUtime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, TrlInUse,_TrlMax,StkSpa, GlobInU, LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize) :- +'$statistics'(Runtime,CPUtime,SYStime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, TrlInUse,_TrlMax,StkSpa, GlobInU, LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize) :- TotalMemory is HpSpa+StkSpa+TrlSpa, format(user_error,'memory (total)~t~d bytes~35+~n', [TotalMemory]), format(user_error,' program space~t~d bytes~35+', [HpSpa]), @@ -71,10 +72,12 @@ statistics :- format(user_error,'~t~3f~12+ sec. runtime~n', [RTime]), CPUTime is float(CPUtime)/1000, format(user_error,'~t~3f~12+ sec. cputime~n', [CPUTime]), + SYSTime is float(SYStime)/1000, + format(user_error,'~t~3f~12+ sec. systime~n', [SYSTime]), WallTime is float(Walltime)/1000, format(user_error,'~t~3f~12+ sec. elapsed time~n~n', [WallTime]), fail. -'$statistics'(_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_). +'$statistics'(_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_). statistics(runtime,[T,L]) :- '$runtime'(T,L). -- 1.5.2.5 ------------------------------------------------------------------------------ This SF.net email is sponsored by: SourcForge Community SourceForge wants to tell your story. http://p.sf.net/sfu/sf-spreadtheword _______________________________________________ Yap-users mailing list Yap-users@... https://lists.sourceforge.net/lists/listinfo/yap-users |
|
|
Re: Performance Issue Feedback (Pablo's problem)
by Vitor Santos Costa-2
::
Rate this Message:
Hi Tony and all
Tony, I included your patch on the YAP sources. I am still navigating through bug requests, I'll try to investigate the issues you raise. > 1. There is a consult I/O performance issue in 5.1.3 MinGW/Cygwin - IT IS > FIXED FOR MINGW BY CURRENT PRE-RELEASE 5.1.4 > Created file of a 20mb one line comment (%) and ':- statistics,halt.'. > Isolates I/O and should have little Yap overhead. > I don't remember making changes to IO between the two, but clearly I did :) Or you'e using different versions of the mingw libraries? YAP uses Unix style IO and that seems to be very expensive with cygwin. I actually find that disappointing, they had a lot of time to put a good act. > MinGW 5.1.3 MinGW 5.1.4 Cygwin 5.1.3 Cygwin 5.1.4 > 4.406 sec. cputime 0.578 sec. cputime 7.594 sec. cputime 7.516 sec. > cputime > 11.250 sec. systime 0.031 sec. systime 0.125 sec. systime 0.110 sec. > systime > 16.875 sec. elapsed 0.625 sec. elapsed 8.109 sec. elapsed 8.166 sec. > elapsed > > Virtual Disk Shared directory NTFS > Linux 5.1.3 Linux 5.1.4 Linux 5.1.3 Linux 5.1.4 > 1.120 sec. cputime 1.060 sec. cputime 0.172 sec. runtime 0.156 sec. > cputime > 0.084 sec. systime 0.080 sec. systime 3.104 sec. systime 3.012 sec. > systime > 1.210 sec. elapsed 1.152 sec. elapsed 5.427 sec. elapsed 4.755 sec. > elapsed > > Note: I added 'systime' using stime/KernelTime to clarify elapsed/cpu > difference. (Git mbox patch attached) > Shared NTFS elapsed includes unaccounted Windows time > > 2. The Cygwin builds all do not restore 'startup'. 'startup' appears to be > built in make but is only circa 2kb after save(startup). As a result, every > time Cygwin Yap starts, it loads pl/boot.yap, adding 0.3-0.4s. Verified that > dcc.fc.up.pt tar.gz has small file. > That should have changed. cygwin used malloc, and save/restore do not work with malloc. > 3. The silent load (-L) problem reported by me is also fixed in 5.1.4 WITH > THE PATCH REMOVED. I suspect that whatever fixed the MinGW performance, also > fixed this. > What do you mean by "THe PATCH removed?" > 4. I discovered a disparity in tail recursion optimization. All versions and > flavours. > > '_repeat2'( _). > '_repeat2'( N) :- N > 1, N2 is N - 1, '_repeat2'( N2). > repeat2( N) :- N > 0, '_repeat2'( N). > '_for2'( I, I, _). > '_for2'( I, C, L) :- C < L, C2 is C + 1, '_for2'( I, C2, L). > for2( A, B, C) :- B =< C, '_for2'( A, B, C). > > for2(_,1,2000000),fail;statistics > repeat2(2000000),fail;statistics > global stack: 4632 in use, 4876 max global stack: 4584 in > use, 8004588 max > It looks like you're leaving choice-points. I'll look into it better. > 5. Discovered a bug in 5.1.4 which is probably the most amusing one I've > ever found and would probably never affect anyone. Not on 5.1.3 and affects > all flavours of 5.1.4. > > 20Mb single line comment file+statistics 20Mb 2000000 line comment > file+statistics > global stack: 4556 in use, 4704 max global stack: 48004532 in > use, 48004544 max > > Note: Cygwin 5.1.4 program took 3x as long as MinGW 5.1.4 to create files. > If stack not preallocated -> YAP ERROR: Global Collided against Local > (00680000--0065FD74) > > Anybody want to employ me as a software destroyer? ;-) > That is strange :( Cheers and thanks for helping, we need people to destroy the system (and make it better :) Vitor > Regards, > Tony Wilson > Durban, South Africa > > PS Don't worry Vitor, people don't bother finding bugs in software they > don't like. > > > >From 14713dafa8a3d4cc3de1138f8219380ad3bb012a Mon Sep 17 00:00:00 2001 > From: Tony Wilson <soduktile@...> > Date: Sun, 18 Jan 2009 04:58:25 +0200 > Subject: [PATCH] Add systime (stime/KernelTime) to statistics/0 > > Caveats: > systime/walltime inconsistency visible on small times (yap -g > statistics,halt) > not serious as cputime/walltime inconsistency pre-existed > systime is not correct for threads > single StartOfTimes_sys and last_time_sys > only tested on Linux (Ubuntu), Cygwin and MinGW (under Cygwin not MSYS) > > diff --git a/C/stdpreds.c b/C/stdpreds.c > index b2a30c1..4bd25b8 100644 > --- a/C/stdpreds.c > +++ b/C/stdpreds.c > @@ -333,6 +333,7 @@ STD_PROTO(static Int p_statistics_trail_info, (void)); > STD_PROTO(static Term mk_argc_list, (void)); > STD_PROTO(static Int p_argv, (void)); > STD_PROTO(static Int p_cputime, (void)); > +STD_PROTO(static Int p_systime, (void)); > STD_PROTO(static Int p_runtime, (void)); > STD_PROTO(static Int p_walltime, (void)); > STD_PROTO(static Int p_access_yap_flags, (void)); > @@ -788,6 +789,15 @@ p_cputime(void) > } > > static Int > +p_systime(void) > +{ > + Int now, interval; > + Yap_systime_interval(&now, &interval); > + return( Yap_unify_constant(ARG1, MkIntegerTerm(now)) && > + Yap_unify_constant(ARG2, MkIntegerTerm(interval)) ); > +} > + > +static Int > p_walltime(void) > { > Int now, interval; > @@ -3908,6 +3918,7 @@ Yap_InitCPreds(void) > Yap_InitCPred("$argv", 1, p_argv, SafePredFlag|HiddenPredFlag); > Yap_InitCPred("$runtime", 2, p_runtime, > SafePredFlag|SyncPredFlag|HiddenPredFlag); > Yap_InitCPred("$cputime", 2, p_cputime, > SafePredFlag|SyncPredFlag|HiddenPredFlag); > + Yap_InitCPred("$systime", 2, p_systime, > SafePredFlag|SyncPredFlag|HiddenPredFlag); > Yap_InitCPred("$walltime", 2, p_walltime, > SafePredFlag|SyncPredFlag|HiddenPredFlag); > Yap_InitCPred("$access_yap_flags", 2, p_access_yap_flags, > SafePredFlag|HiddenPredFlag); > Yap_InitCPred("$set_yap_flags", 2, p_set_yap_flags, > SafePredFlag|SyncPredFlag|HiddenPredFlag); > diff --git a/C/sysbits.c b/C/sysbits.c > index 2def996..e0ca791 100644 > --- a/C/sysbits.c > +++ b/C/sysbits.c > @@ -320,6 +320,8 @@ static struct timeval StartOfTimes; > /* since last call to runtime */ > static struct timeval last_time; > #endif > +static struct timeval last_time_sys; > +static struct timeval StartOfTimes_sys; > > /* store user time in this variable */ > static void > @@ -334,6 +336,8 @@ InitTime (void) > getrusage(RUSAGE_SELF, &rusage); > last_time.tv_sec = StartOfTimes.tv_sec = rusage.ru_utime.tv_sec; > last_time.tv_usec = StartOfTimes.tv_usec = rusage.ru_utime.tv_usec; > + last_time_sys.tv_sec = StartOfTimes_sys.tv_sec = rusage.ru_stime.tv_sec; > + last_time_sys.tv_usec = StartOfTimes_sys.tv_usec = > rusage.ru_stime.tv_usec; > } > > > @@ -360,6 +364,19 @@ void Yap_cputime_interval(Int *now,Int *interval) > last_time.tv_sec = rusage.ru_utime.tv_sec; > } > > +void Yap_systime_interval(Int *now,Int *interval) > +{ > + struct rusage rusage; > + > + getrusage(RUSAGE_SELF, &rusage); > + *now = (rusage.ru_stime.tv_sec - StartOfTimes_sys.tv_sec) * 1000 + > + (rusage.ru_stime.tv_usec - StartOfTimes_sys.tv_usec) / 1000; > + *interval = (rusage.ru_stime.tv_sec - last_time_sys.tv_sec) * 1000 + > + (rusage.ru_stime.tv_usec - last_time_sys.tv_usec) / 1000; > + last_time_sys.tv_usec = rusage.ru_stime.tv_usec; > + last_time_sys.tv_sec = rusage.ru_stime.tv_sec; > +} > + > #elif defined(_WIN32) > > #ifdef __GNUC__ > @@ -389,6 +406,8 @@ void Yap_cputime_interval(Int *now,Int *interval) > > static FILETIME StartOfTimes, last_time; > > +static FILETIME StartOfTimes_sys, last_time_sys; > + > static clock_t TimesStartOfTimes, Times_last_time; > > /* store user time in this variable */ > @@ -407,6 +426,10 @@ InitTime (void) > last_time.dwHighDateTime = UserTime.dwHighDateTime; > StartOfTimes.dwLowDateTime = UserTime.dwLowDateTime; > StartOfTimes.dwHighDateTime = UserTime.dwHighDateTime; > + last_time_sys.dwLowDateTime = KernelTime.dwLowDateTime; > + last_time_sys.dwHighDateTime = KernelTime.dwHighDateTime; > + StartOfTimes_sys.dwLowDateTime = KernelTime.dwLowDateTime; > + StartOfTimes_sys.dwHighDateTime = KernelTime.dwHighDateTime; > } > } > > @@ -477,6 +500,34 @@ void Yap_cputime_interval(Int *now,Int *interval) > } > } > > +void Yap_systime_interval(Int *now,Int *interval) > +{ > + HANDLE hProcess = GetCurrentProcess(); > + FILETIME CreationTime, ExitTime, KernelTime, UserTime; > + if (!GetProcessTimes(hProcess, &CreationTime, &ExitTime, &KernelTime, > &UserTime)) { > + *now = *interval = 0; /* not available */ > + } else { > +#ifdef __GNUC__ > + unsigned long long int t1 = > + sub_utime(KernelTime, StartOfTimes_sys); > + unsigned long long int t2 = > + sub_utime(KernelTime, last_time_sys); > + do_div(t1,10000); > + *now = (Int)t1; > + do_div(t2,10000); > + *interval = (Int)t2; > +#endif > +#ifdef _MSC_VER > + __int64 t1 = *(__int64 *)&KernelTime - *(__int64 *)&StartOfTimes_sys; > + __int64 t2 = *(__int64 *)&KernelTime - *(__int64 *)&last_time_sys; > + *now = (Int)(t1/10000); > + *interval = (Int)(t2/10000); > +#endif > + last_time_sys.dwLowDateTime = KernelTime.dwLowDateTime; > + last_time_sys.dwHighDateTime = KernelTime.dwHighDateTime; > + } > +} > + > #elif HAVE_TIMES > > #if defined(_WIN32) > @@ -520,6 +571,8 @@ void Yap_cputime_interval(Int *now,Int *interval) > > static clock_t StartOfTimes, last_time; > > +static clock_t StartOfTimes_sys, last_time_sys; > + > /* store user time in this variable */ > static void > InitTime (void) > @@ -527,6 +580,7 @@ InitTime (void) > struct tms t; > times (&t); > last_time = StartOfTimes = t.tms_utime; > + last_time_sys = StartOfTimes_sys = t.tms_stime; > } > > UInt > @@ -546,6 +600,15 @@ void Yap_cputime_interval(Int *now,Int *interval) > last_time = t.tms_utime; > } > > +void Yap_systime_interval(Int *now,Int *interval) > +{ > + struct tms t; > + times (&t); > + *now = ((t.tms_stime - StartOfTimes_sys)*1000) / TicksPerSec; > + *interval = (t.tms_stime - last_time_sys) * 1000 / TicksPerSec; > + last_time_sys = t.tms_stime; > +} > + > #else /* HAVE_TIMES */ > > #ifdef SIMICS > @@ -597,6 +660,11 @@ void Yap_cputime_interval(Int *now,Int *interval) > last_time.tv_sec = tp.tv_sec; > } > > +void Yap_systime_interval(Int *now,Int *interval) > +{ > + *now = *interval = 0; /* not available */ > +} > + > #endif /* SIMICS */ > > #ifdef COMMENTED_OUT > diff --git a/H/Yapproto.h b/H/Yapproto.h > index be55677..ef3a955 100644 > --- a/H/Yapproto.h > +++ b/H/Yapproto.h > @@ -313,6 +313,7 @@ void STD_PROTO(Yap_InitSysPath,(void)); > void STD_PROTO(Yap_SetTextFile,(char *)); > #endif > void STD_PROTO(Yap_cputime_interval,(Int *,Int *)); > +void STD_PROTO(Yap_systime_interval,(Int *,Int *)); > void STD_PROTO(Yap_walltime_interval,(Int *,Int *)); > void STD_PROTO(Yap_InitSysbits,(void)); > void STD_PROTO(Yap_InitSysPreds,(void)); > diff --git a/pl/statistics.yap b/pl/statistics.yap > index 41df05e..02a7a5b 100644 > --- a/pl/statistics.yap > +++ b/pl/statistics.yap > @@ -20,6 +20,7 @@ > statistics :- > '$runtime'(Runtime,_), > '$cputime'(CPUtime,_), > + '$systime'(SYStime,_), > '$walltime'(Walltime,_), > '$statistics_heap_info'(HpSpa, HpInUse), > '$statistics_heap_max'(HpMax), > @@ -33,9 +34,9 @@ statistics :- > '$inform_trail_overflows'(NOfTO,TotTOTime), > '$inform_gc'(NOfGC,TotGCTime,TotGCSize), > '$inform_agc'(NOfAGC,TotAGCTime,TotAGCSize), > - '$statistics'(Runtime,CPUtime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, > TrlInUse,TrlMax,StkSpa, GlobInU, > LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize). > + > '$statistics'(Runtime,CPUtime,SYStime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, > TrlInUse,TrlMax,StkSpa, GlobInU, > LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize). > > -'$statistics'(Runtime,CPUtime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, > TrlInUse,_TrlMax,StkSpa, GlobInU, > LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize) > :- > +'$statistics'(Runtime,CPUtime,SYStime,Walltime,HpSpa,HpInUse,HpMax,TrlSpa, > TrlInUse,_TrlMax,StkSpa, GlobInU, > LocInU,GlobMax,LocMax,NOfHO,TotHOTime,NOfSO,TotSOTime,NOfTO,TotTOTime,NOfGC,TotGCTime,TotGCSize,NOfAGC,TotAGCTime,TotAGCSize) > :- > TotalMemory is HpSpa+StkSpa+TrlSpa, > format(user_error,'memory (total)~t~d bytes~35+~n', [TotalMemory]), > format(user_error,' program space~t~d bytes~35+', [HpSpa]), > @@ -71,10 +72,12 @@ statistics :- > format(user_error,'~t~3f~12+ sec. runtime~n', [RTime]), > CPUTime is float(CPUtime)/1000, > format(user_error,'~t~3f~12+ sec. cputime~n', [CPUTime]), > + SYSTime is float(SYStime)/1000, > + format(user_error,'~t~3f~12+ sec. systime~n', [SYSTime]), > WallTime is float(Walltime)/1000, > format(user_error,'~t~3f~12+ sec. elapsed time~n~n', [WallTime]), > fail. > -'$statistics'(_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_). > +'$statistics'(_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_,_). > > statistics(runtime,[T,L]) :- > '$runtime'(T,L). > -- > 1.5.2.5 > > > ------------------------------------------------------------------------------ > This SF.net email is sponsored by: > SourcForge Community > SourceForge wants to tell your story. > http://p.sf.net/sfu/sf-spreadtheword > _______________________________________________ > Yap-users mailing list > Yap-users@... > https://lists.sourceforge.net/lists/listinfo/yap-users > > ------------------------------------------------------------------------------ This SF.net email is sponsored by: SourcForge Community SourceForge wants to tell your story. http://p.sf.net/sfu/sf-spreadtheword _______________________________________________ Yap-users mailing list Yap-users@... https://lists.sourceforge.net/lists/listinfo/yap-users |
|
|
|
|
|
|
|
|
Re: Performance Issue Feedback (Pablo's problem)
by Vitor Santos Costa-2
::
Rate this Message:
Thanks Tony! At first sight this looks like YAP not recovering
correctly the space allocated by readline. Cheers Vitor On Tue, Jan 20, 2009 at 6:26 PM, Tony Wilson <soduktile@...> wrote: > > I sat down thinking it would take an hour or two and it took 5 minutes !!! > This is the FIRST change that I saw doing a diff that looked like a > possible. As you can see no more bars and lots of speed with this one > change. The test shown is writing; I also tested reading and it is fast. > > The commit comment is 'small fixes to compile in Windows again.' 2008-08-19 > 16:50:57 & 2008-08-22 03:59:48 > ( I am starting to love git and especially git-gui :) > > C/iopreds.c line: 291 > > 5.1.3 -> 5.1.4 > > -#ifdef __MINGW32__ > - TRUE /* we cannot trust _isatty in MINGW */ > -#else > _isatty(_fileno(s->u.file.file)) > -#endif > > BEFORE: > ~/minYap3 > $ ./yap.exe -L e:z.yap > | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | ... > program space 1245184 bytes: 1129320 in use, > > stack space 843776 bytes: 5560 in use, > global stack: 4688 in use, > local stack: 872 in use, > trail stack 131068 bytes: 72 in use, > > 0.000 sec. for 0 code, 0 stack, and 0 trail space ove... > 0.000 sec. for 0 garbage collections which collected ... > 0.000 sec. for 0 atom garbage collections which colle... > 13.359 sec. runtime > 13.359 sec. cputime > 36.500 sec. systime > 56.250 sec. elapsed time > > > AFTER: > ~/minYap3 > $ ./yap.exe -L e:z.yap > memory (total) 2220028 bytes > program space 1245184 bytes: 1129320 in use, > > stack space 843776 bytes: 5560 in use, > global stack: 4688 in use, > local stack: 872 in use, > trail stack 131068 bytes: 72 in use, > > 0.000 sec. for 0 code, 0 stack, and 0 trail space ove... > 0.000 sec. for 0 garbage collections which collected ... > 0.000 sec. for 0 atom garbage collections which colle... > 3.140 sec. runtime > 3.140 sec. cputime > 0.281 sec. systime > 4.125 sec. elapsed time > > Now I can relax for the night, my job is done. > > Tony > > ------------------------------------------------------------------------------ This SF.net email is sponsored by: SourcForge Community SourceForge wants to tell your story. http://p.sf.net/sfu/sf-spreadtheword _______________________________________________ Yap-users mailing list Yap-users@... https://lists.sourceforge.net/lists/listinfo/yap-users |
| Free embeddable forum powered by Nabble | Forum Help |
