Re: [petsc-dev] [petsc-maint #69143] petsc-dev performance issues

18 Apr 2011


      If anyone has started work on fixing this, please let me know. Otherwise I'll start shortly.

   Barry

On Apr 18, 2011, at 8:24 AM, Barry Smith wrote:
...
Matt,
Yes, this is the problem.  Since we cannot know if anyone has called a PetscSynchronizedPrintf() it has to call this flush to be safe and that, to be safe, has to have the extra message passing. Even if we handle 1,000 processes at a time, with 100,000 processes it will take 100 stages which is too long.
I think we have to do a major rearchitecturing.  Maybe we want to have a flag (set to false by default) in each ASCII viewer indicating that it has synchronize prints. When the flag is false it skips the entire flush and if a synchronize print is done it generates an error. We'll that is easily done.
Barry
On Apr 18, 2011, at 8:10 AM, Matthew Knepley wrote:
...
On Mon, Apr 18, 2011 at 7:52 AM, Sebastian Steiger <[email protected]>wrote:
...
On 4/18/2011 7:25 AM, Matthew Knepley wrote:
...
On Sun, Apr 17, 2011 at 11:59 PM, Sebastian Steiger <[email protected]
17631 is in
PetscSynchronizedFlush(), a routine which is not called from
KSPMonitorDefault()
--->  PetscViewerASCIIMonitorPrintf()
I am looking over the code, and I think that change is going to be bad for
everyone
because we have
PetscViewerFlush_ASCII()
--> PetscSynchronizedFlush()
     --> ping-pong between 0 and everyone
Anytime someone calls flush, the process cannot just send 0 and move on, it
has
to wait.
Matt
...
...
and thus would not change the performance. My guess is that you have
another
print statement using PetscSynchronizedPrintf/Flush() somewhere in the
code.
Matt
In addition to the KSPMonitor, I've hooked up the petsc output with my
own output system as it is written on the webpage:
PetscErrorCode my_double_petsc_vfprintf(FILE * fd, const char format[],
va_list Argp)
{
     PetscErrorCode ierr;
//PetscFunctionBegin; // <ss> gave problems in petsc-3.2 - not
essential according to Barry and Matt
     if (fd != stdout && fd != stderr) { /* handle regular files */
             ierr = PetscVFPrintfDefault(fd,format,Argp);
PetscMatrixNemo<double>::check_petsc_error(ierr);
     } else {
             char buff[2000];
#if PETSC_VERSION_RELEASE == 1
              int length;
#else
             size_t length;
#endif
             ierr = PetscVSNPrintf(buff, 2000, format, &length, Argp);
PetscMatrixNemo<double>::check_petsc_error(ierr);
             /* now send buff to whatever stream or whatever you want */
             msg << buff;
// flush buffer every 2nd time
             num_double_petsc_lines++;
             if (num_double_petsc_lines==2) {
                     msg.flush();
                     num_double_petsc_lines = 0;
             }
     }
     //PetscFunctionReturn(0);
     return 0;
}
Is that connected to the problem? Please note that the "flush buffer
every 2nd time" does not cause the problems, as it is on my side.
Sebastian
...
Sebastian
On 4/17/2011 9:16 PM, Barry Smith wrote:
...
On Apr 17, 2011, at 8:11 PM, Matthew Knepley wrote:
...
On Sun, Apr 17, 2011 at 8:05 PM, Barry Smith <[email protected]
<mailto:[email protected]>> wrote:
...
...
I don't understand, what is different and why does it slow
everything down?
...
You introduced a ping-pong between 0 and every process for every
call to
...
PetscSynchronizedFlush() in order to "stop a flood of messages to
  0". As
process count increases, this is going to be horrible.
Oh yes, this will do it   Is this being used by one of our
  monitor routines? If so we need to fix our monitors to not use
  synchronized printf. So what in the code is calling this.
...
This is just the kind of thing that MPI should be solving for us,
instead of us
...
putting in bullshit code like this to try and regulate message
  counts. Is there
an MPI construct to manage this?
One could use some kind of all to one to get the messages down
  to process zero.
Barry
...
Matt
Barry
On Apr 17, 2011, at 6:50 PM, Sebastian Steiger wrote:
...
Barry, Matt, Satish,
Found it. r16730 is good, r16731 is bad. Matt was right: when I
turn off
...
...
the petsc messages generated by monitoring the iterations of the
  linear
solver, then the revisions have comparable speed. When I turn it
on,
...
...
...
...
then 16731 is 2-3 times slower.
Please fix!
Best
Sebastian
On 04/15/2011 07:31 AM, Matthew Knepley wrote:
...
On Thu, Apr 14, 2011 at 11:33 PM, Satish Balay
  <[email protected] <mailto:[email protected]>
<mailto:[email protected]
  <mailto:[email protected]>>> wrote:
It would be good to complete the bisection to confirm - but
  could it
 be this?
http://petsc.cs.iit.edu/petsc/petsc-dev/rev/10be2c80ec26
CHKMEMQ is disabled only with --with-errorchecking=0 - but
the
 assumpton for this change was that it would be disabled for
 --with-debugging=0 ?
This is my bet for bad set:
http://petsc.cs.iit.edu/petsc/petsc-dev/rev/ee1bdc170b4d
It introduces new messages, but only of length 1. Is your code
  printing
anything at all
during the run?
Thanks,
Matt
Satish
On Thu, 14 Apr 2011, Sebastian Steiger wrote:
...
I'm sorry, actually 16721 is good and 16733 is bad. So it's 12
 revisions.
On 4/14/2011 9:12 PM, Sebastian Steiger wrote:
...
Hi,
I've pinned it down to 16 revisions: 16721 is good, 16737 is
 bad. The
next bisection step would be 16727, but from the log I see
that
16727-16736 might have some problems. Should I continue or do
 you guys
now have a clue what could cause the factor 2-3 slowdown?
Sebastian
steiger@jaguarpf-login6
:~/src/app-nemo/NEMO/libs/petsc-dev/petsc-dev$
  hg
...
...
...
log -r16721:16737
changeset:   16721:b788c229de4d
parent:      16720:9aafffdcf68b
parent:      16715:e53f46924236
user:        Jed Brown <[email protected]>
date:        Mon Aug 09 17:30:28 2010 -0800
summary:     merge
changeset:   16722:4ca941c57754
user: [email protected]
  <mailto:[email protected]>
 <mailto:[email protected]
  <mailto:[email protected]>>
date:        Tue Aug 10 11:57:11 2010 -0500
summary:     add case of np=1 for
MatGetMultiProcBlock_MPIAIJ()
changeset:   16723:4d6b54981472
user: [email protected]
  <mailto:[email protected]>
 <mailto:[email protected]
  <mailto:[email protected]>>
date:        Tue Aug 10 12:00:14 2010 -0500
summary:     fix memory leak in MatHeaderCopy() and
 MatHeaderReplace()
changeset:   16724:2680bde1c9b8
user: [email protected]
  <mailto:[email protected]> <mailto:[email protected]
  <mailto:[email protected]>>
date:        Thu Aug 12 14:37:43 2010 -0500
summary:     Started adding semismooth stuff.
changeset:   16725:50dceda7151c
user: [email protected]
  <mailto:[email protected]> <mailto:[email protected]
  <mailto:[email protected]>>
date:        Thu Aug 12 14:45:13 2010 -0500
summary:     Defined Infinity and epsilon
changeset:   16726:c0f1b46d675f
user:        hzhang
date:        Fri Aug 13 11:10:37 2010 -0500
summary:     update outputfiles for nightly tests
changeset:   16727:67df4fdba5bd
user: [email protected]
  <mailto:[email protected]>
 <mailto:[email protected]
  <mailto:[email protected]>>
date:        Fri Aug 13 13:25:56 2010 -0500
summary:     add PetscSubcommType in PetscSubcommCreate(); add
PetscSubcommCreate_contiguous().
changeset:   16728:10be2c80ec26
parent:      16723:4d6b54981472
user:        Barry Smith [email protected]
  <mailto:[email protected]>
 <mailto:[email protected] <mailto:[email protected]>>
date:        Tue Aug 10 18:15:10 2010 -0500
summary:     merged CHKMEMQ; into PetscStackPush() and
 PetscStackPop()
changeset:   16729:ef8e7a4583e6
user:        Barry Smith [email protected]
  <mailto:[email protected]>
 <mailto:[email protected] <mailto:[email protected]>>
date:        Thu Aug 12 14:16:40 2010 -0500
summary:     changed MatHeaderCopy() to MatHeaderMerge() and
 improved
comment
changeset:   16730:50055ed8b725
parent:      16729:ef8e7a4583e6
parent:      16725:50dceda7151c
user:        Barry Smith [email protected]
  <mailto:[email protected]>
 <mailto:[email protected] <mailto:[email protected]>>
date:        Thu Aug 12 16:24:48 2010 -0500
summary:     commit after merge
changeset:   16731:ee1bdc170b4d
user:        Barry Smith [email protected]
  <mailto:[email protected]>
 <mailto:[email protected] <mailto:[email protected]>>
date:        Fri Aug 13 13:50:30 2010 -0500
summary:     minor formating of short lines
changeset:   16732:a49d9a4b41bc
parent:      16731:ee1bdc170b4d
parent:      16727:67df4fdba5bd
user:        Barry Smith [email protected]
  <mailto:[email protected]>
 <mailto:[email protected] <mailto:[email protected]>>
date:        Fri Aug 13 13:50:43 2010 -0500
summary:     commit after merge
changeset:   16733:804ce43d15c9
user:        Jed Brown <[email protected]>
date:        Fri Aug 13 11:01:24 2010 -0800
summary:     Update converged reason for Rosenbrock demo to be
 more portable
--
What most experimenters take for granted before they begin their
experiments is infinitely more interesting than any results to
  which
their experiments lead.
-- Norbert Wiener
<bisection-conclusion.txt>
--
What most experimenters take for granted before they begin their
  experiments is infinitely more interesting than any results to which
  their experiments lead.
-- Norbert Wiener
--
What most experimenters take for granted before they begin their
experiments is infinitely more interesting than any results to which
their experiments lead.
-- Norbert Wiener
-- 
What most experimenters take for granted before they begin their experiments
is infinitely more interesting than any results to which their experiments
lead.
-- Norbert Wiener
On Mon, Apr 18, 2011 at 7:52 AM, Sebastian Steiger <[email protected]> wrote:
On 4/18/2011 7:25 AM, Matthew Knepley wrote:
...
On Sun, Apr 17, 2011 at 11:59 PM, Sebastian Steiger <[email protected]
<mailto:[email protected]>> wrote:
On a side note, why did that PetscPrintf function not show up in the log
   summary? That could have spared me the whole bisection process.
I cannot make sense of the problem from your report. The only change in
17631 is in
PetscSynchronizedFlush(), a routine which is not called from
KSPMonitorDefault()
 --->  PetscViewerASCIIMonitorPrintf()
I am looking over the code, and I think that change is going to be bad for everyone
because we have
PetscViewerFlush_ASCII()
 --> PetscSynchronizedFlush()
      --> ping-pong between 0 and everyone
Anytime someone calls flush, the process cannot just send 0 and move on, it has
to wait.
Matt
...
and thus would not change the performance. My guess is that you have another
print statement using PetscSynchronizedPrintf/Flush() somewhere in the code.
Matt
In addition to the KSPMonitor, I've hooked up the petsc output with my
own output system as it is written on the webpage:
PetscErrorCode my_double_petsc_vfprintf(FILE * fd, const char format[],
va_list Argp)
{
      PetscErrorCode ierr;
//PetscFunctionBegin; // <ss> gave problems in petsc-3.2 - not
essential according to Barry and Matt
      if (fd != stdout && fd != stderr) { /* handle regular files */
              ierr = PetscVFPrintfDefault(fd,format,Argp);
PetscMatrixNemo<double>::check_petsc_error(ierr);
      } else {
              char buff[2000];
#if PETSC_VERSION_RELEASE == 1
              int length;
#else
              size_t length;
#endif
              ierr = PetscVSNPrintf(buff, 2000, format, &length, Argp);
PetscMatrixNemo<double>::check_petsc_error(ierr);
              /* now send buff to whatever stream or whatever you want */
              msg << buff;
// flush buffer every 2nd time
              num_double_petsc_lines++;
              if (num_double_petsc_lines==2) {
                      msg.flush();
                      num_double_petsc_lines = 0;
              }
      }
      //PetscFunctionReturn(0);
      return 0;
}
Is that connected to the problem? Please note that the "flush buffer
every 2nd time" does not cause the problems, as it is on my side.
Sebastian
...
Sebastian
On 4/17/2011 9:16 PM, Barry Smith wrote:
...
On Apr 17, 2011, at 8:11 PM, Matthew Knepley wrote:
...
On Sun, Apr 17, 2011 at 8:05 PM, Barry Smith <[email protected]
<mailto:[email protected]>> wrote:
...
...
I don't understand, what is different and why does it slow
everything down?
...
You introduced a ping-pong between 0 and every process for every
call to
...
PetscSynchronizedFlush() in order to "stop a flood of messages to
   0". As
process count increases, this is going to be horrible.
Oh yes, this will do it   Is this being used by one of our
   monitor routines? If so we need to fix our monitors to not use
   synchronized printf. So what in the code is calling this.
...
This is just the kind of thing that MPI should be solving for us,
instead of us
...
putting in bullshit code like this to try and regulate message
   counts. Is there
an MPI construct to manage this?
One could use some kind of all to one to get the messages down
   to process zero.
Barry
...
Matt
Barry
On Apr 17, 2011, at 6:50 PM, Sebastian Steiger wrote:
...
Barry, Matt, Satish,
Found it. r16730 is good, r16731 is bad. Matt was right: when I
turn off
...
...
the petsc messages generated by monitoring the iterations of the
   linear
solver, then the revisions have comparable speed. When I turn it on,
then 16731 is 2-3 times slower.
Please fix!
Best
Sebastian
On 04/15/2011 07:31 AM, Matthew Knepley wrote:
...
On Thu, Apr 14, 2011 at 11:33 PM, Satish Balay
   <[email protected] <mailto:[email protected]>
<mailto:[email protected]
   <mailto:[email protected]>>> wrote:
It would be good to complete the bisection to confirm - but
   could it
  be this?
http://petsc.cs.iit.edu/petsc/petsc-dev/rev/10be2c80ec26
CHKMEMQ is disabled only with --with-errorchecking=0 - but the
  assumpton for this change was that it would be disabled for
  --with-debugging=0 ?
This is my bet for bad set:
http://petsc.cs.iit.edu/petsc/petsc-dev/rev/ee1bdc170b4d
It introduces new messages, but only of length 1. Is your code
   printing
anything at all
during the run?
Thanks,
Matt
Satish
On Thu, 14 Apr 2011, Sebastian Steiger wrote:
...
I'm sorry, actually 16721 is good and 16733 is bad. So it's 12
  revisions.
On 4/14/2011 9:12 PM, Sebastian Steiger wrote:
...
Hi,
I've pinned it down to 16 revisions: 16721 is good, 16737 is
  bad. The
next bisection step would be 16727, but from the log I see that
16727-16736 might have some problems. Should I continue or do
  you guys
now have a clue what could cause the factor 2-3 slowdown?
Sebastian
steiger@jaguarpf-login6:~/src/app-nemo/NEMO/libs/petsc-dev/petsc-dev$
   hg
...
...
...
log -r16721:16737
changeset:   16721:b788c229de4d
parent:      16720:9aafffdcf68b
parent:      16715:e53f46924236
user:        Jed Brown <[email protected]>
date:        Mon Aug 09 17:30:28 2010 -0800
summary:     merge
changeset:   16722:4ca941c57754
user: [email protected]
   <mailto:[email protected]>
  <mailto:[email protected]
   <mailto:[email protected]>>
date:        Tue Aug 10 11:57:11 2010 -0500
summary:     add case of np=1 for MatGetMultiProcBlock_MPIAIJ()
changeset:   16723:4d6b54981472
user: [email protected]
   <mailto:[email protected]>
  <mailto:[email protected]
   <mailto:[email protected]>>
date:        Tue Aug 10 12:00:14 2010 -0500
summary:     fix memory leak in MatHeaderCopy() and
  MatHeaderReplace()
changeset:   16724:2680bde1c9b8
user: [email protected]
   <mailto:[email protected]> <mailto:[email protected]
   <mailto:[email protected]>>
date:        Thu Aug 12 14:37:43 2010 -0500
summary:     Started adding semismooth stuff.
changeset:   16725:50dceda7151c
user: [email protected]
   <mailto:[email protected]> <mailto:[email protected]
   <mailto:[email protected]>>
date:        Thu Aug 12 14:45:13 2010 -0500
summary:     Defined Infinity and epsilon
changeset:   16726:c0f1b46d675f
user:        hzhang
date:        Fri Aug 13 11:10:37 2010 -0500
summary:     update outputfiles for nightly tests
changeset:   16727:67df4fdba5bd
user: [email protected]
   <mailto:[email protected]>
  <mailto:[email protected]
   <mailto:[email protected]>>
date:        Fri Aug 13 13:25:56 2010 -0500
summary:     add PetscSubcommType in PetscSubcommCreate(); add
PetscSubcommCreate_contiguous().
changeset:   16728:10be2c80ec26
parent:      16723:4d6b54981472
user:        Barry Smith [email protected]
   <mailto:[email protected]>
  <mailto:[email protected] <mailto:[email protected]>>
date:        Tue Aug 10 18:15:10 2010 -0500
summary:     merged CHKMEMQ; into PetscStackPush() and
  PetscStackPop()
changeset:   16729:ef8e7a4583e6
user:        Barry Smith [email protected]
   <mailto:[email protected]>
  <mailto:[email protected] <mailto:[email protected]>>
date:        Thu Aug 12 14:16:40 2010 -0500
summary:     changed MatHeaderCopy() to MatHeaderMerge() and
  improved
comment
changeset:   16730:50055ed8b725
parent:      16729:ef8e7a4583e6
parent:      16725:50dceda7151c
user:        Barry Smith [email protected]
   <mailto:[email protected]>
  <mailto:[email protected] <mailto:[email protected]>>
date:        Thu Aug 12 16:24:48 2010 -0500
summary:     commit after merge
changeset:   16731:ee1bdc170b4d
user:        Barry Smith [email protected]
   <mailto:[email protected]>
  <mailto:[email protected] <mailto:[email protected]>>
date:        Fri Aug 13 13:50:30 2010 -0500
summary:     minor formating of short lines
changeset:   16732:a49d9a4b41bc
parent:      16731:ee1bdc170b4d
parent:      16727:67df4fdba5bd
user:        Barry Smith [email protected]
   <mailto:[email protected]>
  <mailto:[email protected] <mailto:[email protected]>>
date:        Fri Aug 13 13:50:43 2010 -0500
summary:     commit after merge
changeset:   16733:804ce43d15c9
user:        Jed Brown <[email protected]>
date:        Fri Aug 13 11:01:24 2010 -0800
summary:     Update converged reason for Rosenbrock demo to be
  more portable
--
What most experimenters take for granted before they begin their
experiments is infinitely more interesting than any results to
   which
their experiments lead.
-- Norbert Wiener
<bisection-conclusion.txt>
--
What most experimenters take for granted before they begin their
   experiments is infinitely more interesting than any results to which
   their experiments lead.
-- Norbert Wiener
--
What most experimenters take for granted before they begin their
experiments is infinitely more interesting than any results to which
their experiments lead.
-- Norbert Wiener
-- 
What most experimenters take for granted before they begin their experiments is infinitely more interesting than any results to which their experiments lead.
-- Norbert Wiener

Barry Smith

tags

participants (1)