[Condor-users] Job remains in idle (worked until I increased pool size)

["Michael O'Donnell" <odonnellm@xxxxxxxx>]

I have a pool of 200 cores with various
OS for Windows machines. Yesterday, I expanded the pool from 100 cores
to 200 cores and since than any jobs that I submit remain in the idle state.
I have evaluated the SchedLod and NegotiatorLog and there is no indication
that a problem exists. I have tried to remove machines from the pool, but
the problem persists. Does anyone have any ideas as to what the problem
might be. I am testing a job that I know will work (ran on friday)?

thank you,
Mike

condor_q -better-analyze:
005.000:  Run analysis summary.
 Of 203 machines,
    203 are rejected by your
job's requirements
      0 reject your job
because of their own requirements
      0 match but are
serving users with a better priority in the pool
      0 match but reject
the job for unknown reasons
      0 match but will
not currently preempt their existing job
      0 match but are
currently offline
      0 are available
to run your job
        No successful
match recorded.
        Last failed
match: Wed Feb 09 11:58:49 2011
        Reason for
last match failure: no match found

WARNING:  Be advised:
   No resources matched request's
constraints

The Requirements _expression_ for your
job is:

( ( target.OpSys == "WINNT51"
|| target.OpSys == "WINNT61" || target.OpSys == "WINNT60"
) ) &&
( target.Arch == "INTEL" )
&& ( target.Disk >= DiskUsage ) &&
( ( ( target.Memory * 1024 ) >= ImageSize
) &&
( ( RequestMemory * 1024 ) >= ImageSize
) ) && ( target.HasFileTransfer ) &&
( target.HasWindowsRunAsOwner &&
( target.LocalCredd is "CM"
) )

    Condition    
                    Machines
Matched    Suggestion
    ---------    
                    ----------------
   ----------
1   ( ( ( 1024 * target.Memory
) >= 4500 ) && ( ( 1024 * ceiling(ifThenElse(JobVMMemory isnt
undefined,JobVMMemory,4.394
531250000000E+000)) ) >= 4500 ) )
           
                     
    0                
  REMOVE
2   ( target.HasWindowsRunAsOwner
&& ( target.LocalCredd is "CM" ) )
           
                     
    0                
  REMOVE
3   ( ( target.OpSys == "WINNT51"
|| target.OpSys == "WINNT61" || target.OpSys == "WINNT60"
) )
           
                     
    203
4   ( target.Arch == "INTEL"
)        203
5   ( target.Disk >= 4500 )
          203
6   ( target.HasFileTransfer )
       203





An excerpt from my SchedLog:
02/09 10:56:18 (pid:2844) SECMAN: startCommand
succeeded.
02/09 10:56:18 (pid:2844) Authorizing
server '*/IP'.
02/09 10:56:18 (pid:2844) SEND [1000]
<IP> <IP>
02/09 10:56:18 (pid:2844) SEND [1000]
<IP> <IP>
02/09 10:56:18 (pid:2844) SEND [199]
<IP> <IP>
02/09 10:56:18 (pid:2844) Sent ad to
1 collectors for odonnellm@xxxxxxxxxx
02/09 10:56:18 (pid:2844) ============
Begin clean_shadow_recs =============
02/09 10:56:18 (pid:2844) ============
End clean_shadow_recs =============
02/09 10:56:18 (pid:2844) Return from
Timer handler 7 (timeout)
02/09 10:56:25 (pid:2844) Calling Handler
<<Negotiator Command>> (4)
02/09 10:56:25 (pid:2844) Activity on
stashed negotiator socket
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=21,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=89,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) 
02/09 10:56:25 (pid:2844) Entered negotiate
02/09 10:56:25 (pid:2844) ## 2. Negotiating
with CM
02/09 10:56:25 (pid:2844) *** SwapSpace
= 2147483647
02/09 10:56:25 (pid:2844) *** ReservedSwap
= 0
02/09 10:56:25 (pid:2844) *** Shadow
Size Estimate = 800
02/09 10:56:25 (pid:2844) *** Start
Limit For Swap = 2684354
02/09 10:56:25 (pid:2844) *** Current
num of active shadows = 0
02/09 10:56:25 (pid:2844) Negotiating
for owner: odonnellm@xxxxxxxxxx
02/09 10:56:25 (pid:2844) AutoCluster:config(JobUniverse,LastCheckpointPlatform,NumCkpts)
invoked
02/09 10:56:25 (pid:2844) Reusing prioritized
runnable job list because nothing has changed.
02/09 10:56:25 (pid:2844) Job 4.0: is
runnable
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=21,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=8,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_write(fd=1228
<IP2>,,size=4096,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_write(fd=1228
<IP>,,size=2077,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) Sent job 4.0
(autocluster=0)
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=21,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=31,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) Job 4.0 rejected:
no match found
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=21,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_read(fd=1228
<IP>,,size=8,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) condor_read():
fd=1228
02/09 10:56:25 (pid:2844) condor_read():
select returned 1
02/09 10:56:25 (pid:2844) condor_write(fd=1228
<IP>,,size=29,timeout=20,flags=0)
02/09 10:56:25 (pid:2844) Out of servers
- 0 jobs matched, 1 jobs idle, 1 jobs rejected
02/09 10:56:25 (pid:2844) Return from
Handler <<Negotiator Command>>
02/09 10:56:30 (pid:2844) Calling Timer
handler 316 (HandleFlushJobQueueLogTimer)
02/09 10:56:30 (pid:2844) Return from
Timer handler 316 (HandleFlushJobQueueLogTimer)
02/09 10:56:31 (pid:2844) ACCEPT from=<IP>
newfd=1276 to=<IP>
02/09 10:56:31 (pid:2844) condor_read(fd=1276
<IP>,,size=4,timeout=1,flags=2)
02/09 10:56:31 (pid:2844) condor_read():
fd=1276
02/09 10:56:31 (pid:2844) condor_read():
select returned 1
02/09 10:56:31 (pid:2844) condor_read(fd=1276
<IP>,,size=5,timeout=1,flags=0)
02/09 10:56:31 (pid:2844) condor_read():
fd=1276
02/09 10:56:31 (pid:2844) condor_read():
select returned 1
02/09 10:56:31 (pid:2844) condor_read(fd=1276
<IP>,,size=391,timeout=1,flags=0)
02/09 10:56:31 (pid:2844) condor_read():
fd=1276
02/09 10:56:31 (pid:2844) condor_read():
select returned 1
02/09 10:56:31 (pid:2844) DC_AUTHENTICATE:
received DC_AUTHENTICATE from <159.189.162.84:2749>
02/09 10:56:31 (pid:2844) DC_AUTHENTICATE:
received following ClassAd:


An excerpt from my NegotiatorLog:
02/09 12:08:43 condor_read(fd=596 collector
at <IP>,,size=3012,timeout=60,flags=0)
02/09 12:08:43 condor_read(): fd=596
02/09 12:08:43 condor_read(): select
returned 1
02/09 12:08:43 CLOSE <159.189.160.37:62623>
fd=596
02/09 12:08:43 Got ads: 292 public and
202 private
02/09 12:08:43 Public ads include 1
submitter, 202 startd
02/09 12:08:43 Entering compute_significant_attrs()
02/09 12:08:43 Leaving compute_significant_attrs()
- result=JobUniverse,LastCheckpointPlatform,NumCkpts
02/09 12:08:43 Phase 2:  Performing
accounting ...
02/09 12:08:43 Phase 3:  Sorting
submitter ads by priority ...
02/09 12:08:43 Phase 4.1:  Negotiating
with schedds ...
02/09 12:08:43     numSlots
= 202
02/09 12:08:43     slotWeightTotal
= 202.000000
02/09 12:08:43     pieLeft
= 202.000
02/09 12:08:43     NormalFactor
= 1.000000
02/09 12:08:43     MaxPrioValue
= 0.500000
02/09 12:08:43     NumSubmitterAds
= 1
02/09 12:08:43   Negotiating with
odonnellm@xxxxxxxxxx at <IP>
02/09 12:08:43 0 seconds so far
02/09 12:08:43   Calculating submitter
limit with the following parameters
02/09 12:08:43     SubmitterPrio
      = 0.500000
02/09 12:08:43     SubmitterPrioFactor
= 1.000000
02/09 12:08:43     submitterShare
     = 1.000000
02/09 12:08:43     submitterAbsShare
  = 1.000000
02/09 12:08:43     submitterLimit
   = 202.000000
02/09 12:08:43     submitterUsage
   = 0.000000
02/09 12:08:43 Socket to odonnellm@xxxxxxxxxx
(<IP>) already in cache, reusing
02/09 12:08:43 condor_write(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=110,timeout=30,flags=0)
02/09 12:08:43     Sending
SEND_JOB_INFO/eom
02/09 12:08:43 condor_write(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=29,timeout=30,flags=0)
02/09 12:08:43     Getting
reply from schedd ...
02/09 12:08:43 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=21,timeout=30,flags=0)
02/09 12:08:43 condor_read(): fd=604
02/09 12:08:43 condor_read(): select
returned 1
02/09 12:08:43 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=4075,timeout=30,flags=0)
02/09 12:08:43 condor_read(): fd=604
02/09 12:08:43 condor_read(): select
returned 1
02/09 12:08:43 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=21,timeout=30,flags=0)
02/09 12:08:43 condor_read(): fd=604
02/09 12:08:43 condor_read(): select
returned 1
02/09 12:08:43 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=2056,timeout=30,flags=0)
02/09 12:08:43 condor_read(): fd=604
02/09 12:08:43 condor_read(): select
returned 1
02/09 12:08:43     Got JOB_INFO
command; getting classad/eom
02/09 12:08:43     Request
00005.00000:
02/09 12:08:43 matchmakingAlgorithm:
limit 202.000000 used 0.000000 pieLeft 202.000000
02/09 12:08:43 FileLock::obtain(1) -
@1297278523.987000 lock on C:\Condor\log\negotiator_sql.log now WRITE
02/09 12:08:44 FileLock::obtain(2) -
@1297278524.003000 lock on C:\Condor\log\negotiator_sql.log now UNLOCKED
02/09 12:08:44      
Rejected 5.0 odonnellm@xxxxxxxxxx <IP>: no match found
02/09 12:08:44 condor_write(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=52,timeout=30,flags=0)
02/09 12:08:44     Sending
SEND_JOB_INFO/eom
02/09 12:08:44 condor_write(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=29,timeout=30,flags=0)
02/09 12:08:44     Getting
reply from schedd ...
02/09 12:08:44 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=21,timeout=30,flags=0)
02/09 12:08:44 condor_read(): fd=604
02/09 12:08:44 condor_read(): select
returned 1
02/09 12:08:44 condor_read(fd=604 schedd
odonnellm@xxxxxxxxxx,,size=8,timeout=30,flags=0)
02/09 12:08:44 condor_read(): fd=604
02/09 12:08:44 condor_read(): select
returned 1
02/09 12:08:44     Got NO_MORE_JOBS;
 done negotiating
02/09 12:08:44   Submitter odonnellm@xxxxxxxxxx
got all it wants; removing it.
02/09 12:08:44 ---------- Finished Negotiation
Cycle ----------