Hi, just in case, I attache two log snippets, containing few negiotiator cycles with and without NEGOTIATOR_INTERVALL enabled.
Cheers, Henning
04/08/20 12:55:46 ---------- Started Negotiation Cycle ---------- 04/08/20 12:55:46 Phase 1: Obtaining ads from collector ... 04/08/20 12:55:46 Getting startd private ads ... 04/08/20 12:55:46 Trying to query collector <10.20.60.65:9618> 04/08/20 12:55:46 Getting Scheduler, Submitter and Machine ads ... 04/08/20 12:55:46 Trying to query collector <10.20.60.65:9618> 04/08/20 12:55:46 Sorting 4 ads ... 04/08/20 12:55:46 Ignoring submitter prod.atlascondor@atlas.local from schedd at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4> with no requested jobs 04/08/20 12:55:46 Got ads: 4 public and 1 private 04/08/20 12:55:46 Public ads include 1 submitter, 1 startd 04/08/20 12:55:46 Phase 2: Performing accounting ... 04/08/20 12:55:46 Entering compute_significant_attrs() 04/08/20 12:55:46 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobStart,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 12:55:46 Phase 3: Sorting submitter ads by priority ... 04/08/20 12:55:46 Starting prefetch round; 1 potential prefetches to do. 04/08/20 12:55:46 Assigned 1 units of work for prefetching. 04/08/20 12:55:46 Starting prefetch loop. 04/08/20 12:55:46 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 12:55:46 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 12:55:46 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 12:55:46 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 12:55:46 Getting reply from schedd ... 04/08/20 12:55:46 Prefetch negotiation would block. 04/08/20 12:55:46 Waiting on the results of 1 negotiation sessions. 04/08/20 12:55:46 Getting reply from schedd ... 04/08/20 12:55:46 Got JOB_INFO command; getting classad/eom 04/08/20 12:55:46 Getting reply from schedd ... 04/08/20 12:55:46 Got JOB_INFO command; getting classad/eom 04/08/20 12:55:46 Getting reply from schedd ... 04/08/20 12:55:46 Got JOB_INFO command; getting classad/eom 04/08/20 12:55:46 Getting reply from schedd ... 04/08/20 12:55:46 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 12:55:46 Send END_NEGOTIATE to remote schedd 04/08/20 12:55:46 Assigned 0 units of work for prefetching. 04/08/20 12:55:46 Prefetch summary: 1 attempted, 1 successful. 04/08/20 12:55:46 Phase 4.1: Negotiating with schedds ... 04/08/20 12:55:46 numSlots = 1 (after trimming=1) 04/08/20 12:55:46 slotWeightTotal = 4.000000 04/08/20 12:55:46 minSlotWeight = 4.000000 04/08/20 12:55:46 pieLeft = 4.000 04/08/20 12:55:46 NormalFactor = 1.000000 04/08/20 12:55:46 MaxPrioValue = 14967.540039 04/08/20 12:55:46 NumSubmitterAds = 1 04/08/20 12:55:46 Negotiating with prod.fehrmann@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4> 04/08/20 12:55:46 0 seconds so far for this submitter 04/08/20 12:55:46 0 seconds so far for this schedd 04/08/20 12:55:46 Calculating submitter limit with the following parameters 04/08/20 12:55:46 SubmitterPrio = 14967.540039 04/08/20 12:55:46 SubmitterPrioFactor = 10000.000000 04/08/20 12:55:46 submitterShare = 1.000000 04/08/20 12:55:46 submitterAbsShare = 1.000000 04/08/20 12:55:46 submitterLimit = 4.000000 04/08/20 12:55:46 submitterUsage = 0.000000 04/08/20 12:55:46 Using resource request list from cache. 04/08/20 12:55:46 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 12:55:46 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 12:55:46 Request 00021.00000: autocluster 1 (request count 1 of 1) 04/08/20 12:55:46 matchmakingAlgorithm: limit 4.000000 used 0.000000 pieLeft 4.000000 04/08/20 12:55:46 Sending PERMISSION, claim id, startdAd to schedd 04/08/20 12:55:46 Notifying the accountant 04/08/20 12:55:46 Successfully matched with slot1@a3305.atlas.local 04/08/20 12:55:46 Match completed, match cost= 4 04/08/20 12:55:46 Over submitter resource limit (4.000000, used 4.000000) ... only consider startd ranks 04/08/20 12:55:46 Request 00021.00001: autocluster 2 (request count 1 of 1) 04/08/20 12:55:46 matchmakingAlgorithm: limit 4.000000 used 4.000000 pieLeft 0.000000 04/08/20 12:55:46 Request 00021.00002: autocluster 1 (request count 1 of 2) 04/08/20 12:55:46 matchmakingAlgorithm: limit 4.000000 used 4.000000 pieLeft 0.000000 04/08/20 12:55:46 Send END_NEGOTIATE to remote schedd 04/08/20 12:55:46 This submitter hit its submitterLimit. 04/08/20 12:55:46 resources used scheddUsed= 4.000000 04/08/20 12:55:46 negotiateWithGroup resources used submitterAds length 1 04/08/20 12:55:46 ---------- Finished Negotiation Cycle ---------- 04/08/20 12:55:46 Updating collector with accounting information 04/08/20 12:55:46 Trying to update collector <10.20.60.65:9618> 04/08/20 12:55:46 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 12:55:46 Trying to update collector <10.20.60.65:9618> 04/08/20 12:55:46 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 12:55:46 Done Updating collector with accounting information 04/08/20 12:59:26 Getting monitoring info for pid 639929 04/08/20 12:59:36 ---------- Started Negotiation Cycle ---------- 04/08/20 12:59:36 Phase 1: Obtaining ads from collector ... 04/08/20 12:59:36 Getting startd private ads ... 04/08/20 12:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 12:59:36 Getting Scheduler, Submitter and Machine ads ... 04/08/20 12:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 12:59:36 Sorting 8 ads ... 04/08/20 12:59:36 Got ads: 8 public and 5 private 04/08/20 12:59:36 Public ads include 2 submitter, 5 startd 04/08/20 12:59:36 Phase 2: Performing accounting ... 04/08/20 12:59:36 Entering compute_significant_attrs() 04/08/20 12:59:36 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 12:59:36 Phase 3: Sorting submitter ads by priority ... 04/08/20 12:59:36 Starting prefetch round; 2 potential prefetches to do. 04/08/20 12:59:36 Assigned 1 units of work for prefetching. 04/08/20 12:59:36 Starting prefetch loop. 04/08/20 12:59:36 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 12:59:36 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 12:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 12:59:36 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Prefetch negotiation would block. 04/08/20 12:59:36 Waiting on the results of 1 negotiation sessions. 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Got JOB_INFO command; getting classad/eom 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Got JOB_INFO command; getting classad/eom 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 12:59:36 Send END_NEGOTIATE to remote schedd 04/08/20 12:59:36 Assigned 1 units of work for prefetching. 04/08/20 12:59:36 Starting prefetch loop. 04/08/20 12:59:36 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 12:59:36 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 12:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 12:59:36 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Prefetch negotiation would block. 04/08/20 12:59:36 Waiting on the results of 1 negotiation sessions. 04/08/20 12:59:36 Getting reply from schedd ... 04/08/20 12:59:36 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 12:59:36 Assigned 0 units of work for prefetching. 04/08/20 12:59:36 Prefetch summary: 2 attempted, 2 successful. 04/08/20 12:59:36 Phase 4.1: Negotiating with schedds ... 04/08/20 12:59:36 numSlots = 5 (after trimming=5) 04/08/20 12:59:36 slotWeightTotal = 4.000000 04/08/20 12:59:36 minSlotWeight = 0.000000 04/08/20 12:59:36 pieLeft = 3.727 04/08/20 12:59:36 NormalFactor = 14.631510 04/08/20 12:59:36 MaxPrioValue = 15013.690430 04/08/20 12:59:36 NumSubmitterAds = 2 04/08/20 12:59:36 Negotiating with prod.atlascondor@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4> 04/08/20 12:59:36 0 seconds so far for this submitter 04/08/20 12:59:36 0 seconds so far for this schedd 04/08/20 12:59:36 Calculating submitter limit with the following parameters 04/08/20 12:59:36 SubmitterPrio = 1101.395996 04/08/20 12:59:36 SubmitterPrioFactor = 1000.000000 04/08/20 12:59:36 submitterShare = 0.931654 04/08/20 12:59:36 submitterAbsShare = 0.909091 04/08/20 12:59:36 submitterLimit = 3.726617 04/08/20 12:59:36 submitterUsage = 0.000000 04/08/20 12:59:36 Using resource request list from cache. 04/08/20 12:59:36 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 12:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 12:59:36 Request 00020.00000: autocluster 3 (request count 1 of 1) 04/08/20 12:59:36 matchmakingAlgorithm: limit 3.726617 used 0.000000 pieLeft 3.726617 04/08/20 12:59:36 Request 00020.00001: autocluster 4 (request count 1 of 1) 04/08/20 12:59:36 matchmakingAlgorithm: limit 3.726617 used 0.000000 pieLeft 3.726617 04/08/20 12:59:36 Send END_NEGOTIATE to remote schedd 04/08/20 12:59:36 Submitter prod.atlascondor@atlas.local got all it wants; removing it. 04/08/20 12:59:36 resources used by prod.atlascondor@atlas.local are 0.000000 04/08/20 12:59:36 Negotiating with prod.fehrmann@atlas.local skipped because no idle jobs 04/08/20 12:59:36 Submitter prod.fehrmann@atlas.local got all it wants; removing it. 04/08/20 12:59:36 resources used by prod.fehrmann@atlas.local are 4.000000 04/08/20 12:59:36 resources used scheddUsed= 4.000000 04/08/20 12:59:36 negotiateWithGroup resources used submitterAds length 0 04/08/20 12:59:36 ---------- Finished Negotiation Cycle ---------- 04/08/20 12:59:36 Updating collector with accounting information 04/08/20 12:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 12:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 12:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 12:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 12:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 12:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 12:59:36 Done Updating collector with accounting information 04/08/20 13:00:26 enter Matchmaker::updateCollector 04/08/20 13:00:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:00:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:00:26 exit Matchmaker::UpdateCollector 04/08/20 13:03:26 Getting monitoring info for pid 639929 04/08/20 13:05:26 enter Matchmaker::updateCollector 04/08/20 13:05:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:05:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:05:26 exit Matchmaker::UpdateCollector 04/08/20 13:07:26 Getting monitoring info for pid 639929 04/08/20 13:10:26 enter Matchmaker::updateCollector 04/08/20 13:10:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:10:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:10:26 exit Matchmaker::UpdateCollector 04/08/20 13:11:26 Getting monitoring info for pid 639929 04/08/20 13:12:31 DaemonKeepAlive: in SendAliveToParent() 04/08/20 13:12:31 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 13:12:31 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 13:12:31 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 13:15:26 enter Matchmaker::updateCollector 04/08/20 13:15:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:15:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:15:26 exit Matchmaker::UpdateCollector 04/08/20 13:15:26 Getting monitoring info for pid 639929 04/08/20 13:19:26 Getting monitoring info for pid 639929 04/08/20 13:20:26 enter Matchmaker::updateCollector 04/08/20 13:20:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:20:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:20:26 exit Matchmaker::UpdateCollector 04/08/20 13:23:26 Getting monitoring info for pid 639929 04/08/20 13:25:26 enter Matchmaker::updateCollector 04/08/20 13:25:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:25:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:25:26 exit Matchmaker::UpdateCollector 04/08/20 13:27:26 Getting monitoring info for pid 639929 04/08/20 13:30:26 enter Matchmaker::updateCollector 04/08/20 13:30:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:30:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:30:26 exit Matchmaker::UpdateCollector 04/08/20 13:31:26 Getting monitoring info for pid 639929 04/08/20 13:31:47 DaemonKeepAlive: in SendAliveToParent() 04/08/20 13:31:47 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 13:31:47 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 13:31:47 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 13:35:26 enter Matchmaker::updateCollector 04/08/20 13:35:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:35:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:35:26 exit Matchmaker::UpdateCollector 04/08/20 13:35:26 Getting monitoring info for pid 639929 04/08/20 13:39:26 Getting monitoring info for pid 639929 04/08/20 13:40:26 enter Matchmaker::updateCollector 04/08/20 13:40:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:40:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:40:26 exit Matchmaker::UpdateCollector 04/08/20 13:43:26 Getting monitoring info for pid 639929 04/08/20 13:45:26 enter Matchmaker::updateCollector 04/08/20 13:45:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:45:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:45:26 exit Matchmaker::UpdateCollector 04/08/20 13:47:26 Getting monitoring info for pid 639929 04/08/20 13:50:26 enter Matchmaker::updateCollector 04/08/20 13:50:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:50:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:50:26 exit Matchmaker::UpdateCollector 04/08/20 13:51:03 DaemonKeepAlive: in SendAliveToParent() 04/08/20 13:51:03 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 13:51:03 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 13:51:03 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 13:51:26 Getting monitoring info for pid 639929 04/08/20 13:55:26 enter Matchmaker::updateCollector 04/08/20 13:55:26 Trying to update collector <10.20.60.65:9618> 04/08/20 13:55:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:55:26 exit Matchmaker::UpdateCollector 04/08/20 13:55:26 Getting monitoring info for pid 639929 04/08/20 13:59:26 Getting monitoring info for pid 639929 04/08/20 13:59:36 ---------- Started Negotiation Cycle ---------- 04/08/20 13:59:36 Phase 1: Obtaining ads from collector ... 04/08/20 13:59:36 Getting startd private ads ... 04/08/20 13:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 13:59:36 Getting Scheduler, Submitter and Machine ads ... 04/08/20 13:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 13:59:36 Sorting 8 ads ... 04/08/20 13:59:36 Got ads: 8 public and 5 private 04/08/20 13:59:36 Public ads include 2 submitter, 5 startd 04/08/20 13:59:36 Phase 2: Performing accounting ... 04/08/20 13:59:36 Entering compute_significant_attrs() 04/08/20 13:59:36 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 13:59:37 Phase 3: Sorting submitter ads by priority ... 04/08/20 13:59:37 Starting prefetch round; 2 potential prefetches to do. 04/08/20 13:59:37 Assigned 1 units of work for prefetching. 04/08/20 13:59:37 Starting prefetch loop. 04/08/20 13:59:37 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 13:59:37 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 13:59:37 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 13:59:37 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 13:59:37 Getting reply from schedd ... 04/08/20 13:59:37 Got JOB_INFO command; getting classad/eom 04/08/20 13:59:37 Getting reply from schedd ... 04/08/20 13:59:37 Got JOB_INFO command; getting classad/eom 04/08/20 13:59:37 Getting reply from schedd ... 04/08/20 13:59:37 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 13:59:37 Prefetch negotiation immediately finished. 04/08/20 13:59:37 Send END_NEGOTIATE to remote schedd 04/08/20 13:59:37 Assigned 1 units of work for prefetching. 04/08/20 13:59:37 Starting prefetch loop. 04/08/20 13:59:37 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 13:59:37 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 13:59:37 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 13:59:37 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 13:59:37 Getting reply from schedd ... 04/08/20 13:59:37 Prefetch negotiation would block. 04/08/20 13:59:37 Waiting on the results of 1 negotiation sessions. 04/08/20 13:59:37 Getting reply from schedd ... 04/08/20 13:59:37 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 13:59:37 Assigned 0 units of work for prefetching. 04/08/20 13:59:37 Prefetch summary: 2 attempted, 2 successful. 04/08/20 13:59:37 Phase 4.1: Negotiating with schedds ... 04/08/20 13:59:37 numSlots = 5 (after trimming=5) 04/08/20 13:59:37 slotWeightTotal = 4.000000 04/08/20 13:59:37 minSlotWeight = 0.000000 04/08/20 13:59:37 pieLeft = 3.745 04/08/20 13:59:37 NormalFactor = 15.695700 04/08/20 13:59:37 MaxPrioValue = 15725.000000 04/08/20 13:59:37 NumSubmitterAds = 2 04/08/20 13:59:37 Negotiating with prod.atlascondor@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4> 04/08/20 13:59:37 0 seconds so far for this submitter 04/08/20 13:59:37 0 seconds so far for this schedd 04/08/20 13:59:37 Calculating submitter limit with the following parameters 04/08/20 13:59:37 SubmitterPrio = 1070.040894 04/08/20 13:59:37 SubmitterPrioFactor = 1000.000000 04/08/20 13:59:37 submitterShare = 0.936288 04/08/20 13:59:37 submitterAbsShare = 0.909091 04/08/20 13:59:37 submitterLimit = 3.745153 04/08/20 13:59:37 submitterUsage = 0.000000 04/08/20 13:59:37 Using resource request list from cache. 04/08/20 13:59:37 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 13:59:37 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 13:59:37 Request 00020.00000: autocluster 3 (request count 1 of 1) 04/08/20 13:59:37 matchmakingAlgorithm: limit 3.745153 used 0.000000 pieLeft 3.745153 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00215ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01621ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.00405ms] time() --> 1586354377 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.07701ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: [0.00095ms] 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.18191ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00095ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.05007ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01287ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.10490ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.18811ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: [0.00095ms] RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00119ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01287ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.08297ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: [0.00119ms] 1 --> 1 04/08/20 13:59:37 Classad debug: [0.03004ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.20695ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00095ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01311ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: [0.00119ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.07010ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.14877ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Request 00020.00001: autocluster 4 (request count 1 of 1) 04/08/20 13:59:37 matchmakingAlgorithm: limit 3.745153 used 0.000000 pieLeft 3.745153 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00095ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01383ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.00095ms] time() --> 1586354377 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01311ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.08798ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01192ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.17095ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01287ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01383ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.07510ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.15998ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: [0.00095ms] RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00095ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01383ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.12589ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: [0.00119ms] 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.23389ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Classad debug: RemoteUserPrio --> 15725 04/08/20 13:59:37 Classad debug: [0.00095ms] SubmitterUserPrio --> 1070.04 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.01502ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: time() --> 1586354377 04/08/20 13:59:37 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 13:59:37 Classad debug: [0.03290ms] JobStart --> 1586350546 04/08/20 13:59:37 Classad debug: [0.11206ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 3831 04/08/20 13:59:37 Classad debug: 1 --> 1 04/08/20 13:59:37 Classad debug: [0.01192ms] MinRunTimeHours --> 1 04/08/20 13:59:37 Classad debug: [0.22483ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 13:59:37 Send END_NEGOTIATE to remote schedd 04/08/20 13:59:37 Submitter prod.atlascondor@atlas.local got all it wants; removing it. 04/08/20 13:59:37 resources used by prod.atlascondor@atlas.local are 0.000000 04/08/20 13:59:37 Negotiating with prod.fehrmann@atlas.local skipped because no idle jobs 04/08/20 13:59:37 Submitter prod.fehrmann@atlas.local got all it wants; removing it. 04/08/20 13:59:37 resources used by prod.fehrmann@atlas.local are 4.000000 04/08/20 13:59:37 resources used scheddUsed= 4.000000 04/08/20 13:59:37 negotiateWithGroup resources used submitterAds length 0 04/08/20 13:59:37 ---------- Finished Negotiation Cycle ---------- 04/08/20 13:59:37 Updating collector with accounting information 04/08/20 13:59:37 Trying to update collector <10.20.60.65:9618> 04/08/20 13:59:37 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:59:37 Trying to update collector <10.20.60.65:9618> 04/08/20 13:59:37 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:59:37 Trying to update collector <10.20.60.65:9618> 04/08/20 13:59:37 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 13:59:37 Done Updating collector with accounting information 04/08/20 14:00:26 enter Matchmaker::updateCollector 04/08/20 14:00:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:00:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:00:26 exit Matchmaker::UpdateCollector 04/08/20 14:03:26 Getting monitoring info for pid 639929 04/08/20 14:05:26 enter Matchmaker::updateCollector 04/08/20 14:05:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:05:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:05:26 exit Matchmaker::UpdateCollector 04/08/20 14:07:26 Getting monitoring info for pid 639929 04/08/20 14:10:19 DaemonKeepAlive: in SendAliveToParent() 04/08/20 14:10:19 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 14:10:19 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 14:10:19 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 14:10:26 enter Matchmaker::updateCollector 04/08/20 14:10:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:10:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:10:26 exit Matchmaker::UpdateCollector 04/08/20 14:11:26 Getting monitoring info for pid 639929 04/08/20 14:15:26 enter Matchmaker::updateCollector 04/08/20 14:15:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:15:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:15:26 exit Matchmaker::UpdateCollector 04/08/20 14:15:26 Getting monitoring info for pid 639929 04/08/20 14:19:26 Getting monitoring info for pid 639929 04/08/20 14:20:26 enter Matchmaker::updateCollector 04/08/20 14:20:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:20:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:20:26 exit Matchmaker::UpdateCollector 04/08/20 14:23:26 Getting monitoring info for pid 639929 04/08/20 14:25:26 enter Matchmaker::updateCollector 04/08/20 14:25:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:25:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:25:26 exit Matchmaker::UpdateCollector 04/08/20 14:27:26 Getting monitoring info for pid 639929 04/08/20 14:29:35 DaemonKeepAlive: in SendAliveToParent() 04/08/20 14:29:35 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 14:29:35 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 14:29:35 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 14:30:26 enter Matchmaker::updateCollector 04/08/20 14:30:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:30:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:30:26 exit Matchmaker::UpdateCollector 04/08/20 14:31:26 Getting monitoring info for pid 639929 04/08/20 14:35:26 enter Matchmaker::updateCollector 04/08/20 14:35:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:35:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:35:26 exit Matchmaker::UpdateCollector 04/08/20 14:35:26 Getting monitoring info for pid 639929 04/08/20 14:39:26 Getting monitoring info for pid 639929 04/08/20 14:40:26 enter Matchmaker::updateCollector 04/08/20 14:40:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:40:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:40:26 exit Matchmaker::UpdateCollector 04/08/20 14:43:26 Getting monitoring info for pid 639929 04/08/20 14:45:26 enter Matchmaker::updateCollector 04/08/20 14:45:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:45:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:45:26 exit Matchmaker::UpdateCollector 04/08/20 14:47:26 Getting monitoring info for pid 639929 04/08/20 14:48:51 DaemonKeepAlive: in SendAliveToParent() 04/08/20 14:48:51 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 14:48:51 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 14:48:51 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 14:50:26 enter Matchmaker::updateCollector 04/08/20 14:50:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:50:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:50:26 exit Matchmaker::UpdateCollector 04/08/20 14:51:26 Getting monitoring info for pid 639929 04/08/20 14:55:26 enter Matchmaker::updateCollector 04/08/20 14:55:26 Trying to update collector <10.20.60.65:9618> 04/08/20 14:55:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:55:26 exit Matchmaker::UpdateCollector 04/08/20 14:55:26 Getting monitoring info for pid 639929 04/08/20 14:59:26 Getting monitoring info for pid 639929 04/08/20 14:59:36 ---------- Started Negotiation Cycle ---------- 04/08/20 14:59:36 Phase 1: Obtaining ads from collector ... 04/08/20 14:59:36 Getting startd private ads ... 04/08/20 14:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 14:59:36 Getting Scheduler, Submitter and Machine ads ... 04/08/20 14:59:36 Trying to query collector <10.20.60.65:9618> 04/08/20 14:59:36 Sorting 8 ads ... 04/08/20 14:59:36 Got ads: 8 public and 5 private 04/08/20 14:59:36 Public ads include 2 submitter, 5 startd 04/08/20 14:59:36 Phase 2: Performing accounting ... 04/08/20 14:59:36 Entering compute_significant_attrs() 04/08/20 14:59:36 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 14:59:36 Phase 3: Sorting submitter ads by priority ... 04/08/20 14:59:36 Starting prefetch round; 2 potential prefetches to do. 04/08/20 14:59:36 Assigned 1 units of work for prefetching. 04/08/20 14:59:36 Starting prefetch loop. 04/08/20 14:59:36 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 14:59:36 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 14:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 14:59:36 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 14:59:36 Getting reply from schedd ... 04/08/20 14:59:36 Got JOB_INFO command; getting classad/eom 04/08/20 14:59:36 Getting reply from schedd ... 04/08/20 14:59:36 Got JOB_INFO command; getting classad/eom 04/08/20 14:59:36 Getting reply from schedd ... 04/08/20 14:59:36 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 14:59:36 Prefetch negotiation immediately finished. 04/08/20 14:59:36 Send END_NEGOTIATE to remote schedd 04/08/20 14:59:36 Assigned 1 units of work for prefetching. 04/08/20 14:59:36 Starting prefetch loop. 04/08/20 14:59:36 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 14:59:36 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 14:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 14:59:36 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 14:59:36 Getting reply from schedd ... 04/08/20 14:59:36 Prefetch negotiation would block. 04/08/20 14:59:36 Waiting on the results of 1 negotiation sessions. 04/08/20 14:59:36 Getting reply from schedd ... 04/08/20 14:59:36 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 14:59:36 Assigned 0 units of work for prefetching. 04/08/20 14:59:36 Prefetch summary: 2 attempted, 2 successful. 04/08/20 14:59:36 Phase 4.1: Negotiating with schedds ... 04/08/20 14:59:36 numSlots = 5 (after trimming=5) 04/08/20 14:59:36 slotWeightTotal = 4.000000 04/08/20 14:59:36 minSlotWeight = 0.000000 04/08/20 14:59:36 pieLeft = 3.762 04/08/20 14:59:36 NormalFactor = 16.791066 04/08/20 14:59:36 MaxPrioValue = 16416.060547 04/08/20 14:59:36 NumSubmitterAds = 2 04/08/20 14:59:36 Negotiating with prod.atlascondor@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4> 04/08/20 14:59:36 0 seconds so far for this submitter 04/08/20 14:59:36 0 seconds so far for this schedd 04/08/20 14:59:36 Calculating submitter limit with the following parameters 04/08/20 14:59:36 SubmitterPrio = 1039.578979 04/08/20 14:59:36 SubmitterPrioFactor = 1000.000000 04/08/20 14:59:36 submitterShare = 0.940445 04/08/20 14:59:36 submitterAbsShare = 0.909091 04/08/20 14:59:36 submitterLimit = 3.761778 04/08/20 14:59:36 submitterUsage = 0.000000 04/08/20 14:59:36 Using resource request list from cache. 04/08/20 14:59:36 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=639885_7712_4>) already in cache, reusing 04/08/20 14:59:36 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 14:59:36 Request 00020.00000: autocluster 3 (request count 1 of 1) 04/08/20 14:59:36 matchmakingAlgorithm: limit 3.761778 used 0.000000 pieLeft 3.761778 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00191ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.03195ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01311ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.10085ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01216ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.20313ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01216ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.06509ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01287ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.14591ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01287ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01287ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.08392ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.16308ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00119ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.02789ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.08297ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.16093ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Request 00020.00001: autocluster 4 (request count 1 of 1) 04/08/20 14:59:36 matchmakingAlgorithm: limit 3.761778 used 0.000000 pieLeft 3.761778 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01502ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.00095ms] time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.07105ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.18120ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.02885ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.04601ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.11683ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01788ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.20385ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01383ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01407ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.07105ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.15616ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Classad debug: RemoteUserPrio --> 16416.1 04/08/20 14:59:36 Classad debug: [0.00095ms] SubmitterUserPrio --> 1039.58 04/08/20 14:59:36 Classad debug: [0.00095ms] 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.03099ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.00095ms] time() --> 1586357976 04/08/20 14:59:36 Classad debug: 1586350546 --> 1586350546 04/08/20 14:59:36 Classad debug: [0.01311ms] JobStart --> 1586350546 04/08/20 14:59:36 Classad debug: [0.08392ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 7430 04/08/20 14:59:36 Classad debug: 1 --> 1 04/08/20 14:59:36 Classad debug: [0.01287ms] MinRunTimeHours --> 1 04/08/20 14:59:36 Classad debug: [0.17405ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 14:59:36 Send END_NEGOTIATE to remote schedd 04/08/20 14:59:36 Submitter prod.atlascondor@atlas.local got all it wants; removing it. 04/08/20 14:59:36 resources used by prod.atlascondor@atlas.local are 0.000000 04/08/20 14:59:36 Negotiating with prod.fehrmann@atlas.local skipped because no idle jobs 04/08/20 14:59:36 Submitter prod.fehrmann@atlas.local got all it wants; removing it. 04/08/20 14:59:36 resources used by prod.fehrmann@atlas.local are 4.000000 04/08/20 14:59:36 resources used scheddUsed= 4.000000 04/08/20 14:59:36 negotiateWithGroup resources used submitterAds length 0 04/08/20 14:59:36 ---------- Finished Negotiation Cycle ---------- 04/08/20 14:59:36 Updating collector with accounting information 04/08/20 14:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 14:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 14:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:59:36 Trying to update collector <10.20.60.65:9618> 04/08/20 14:59:36 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 14:59:36 Done Updating collector with accounting information 04/08/20 15:00:26 enter Matchmaker::updateCollector 04/08/20 15:00:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:00:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:00:26 exit Matchmaker::UpdateCollector 04/08/20 15:03:26 Getting monitoring info for pid 639929 04/08/20 15:05:26 enter Matchmaker::updateCollector 04/08/20 15:05:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:05:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:05:26 exit Matchmaker::UpdateCollector 04/08/20 15:07:26 Getting monitoring info for pid 639929 04/08/20 15:08:07 DaemonKeepAlive: in SendAliveToParent() 04/08/20 15:08:07 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 15:08:07 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 15:08:07 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 15:10:26 enter Matchmaker::updateCollector 04/08/20 15:10:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:10:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:10:26 exit Matchmaker::UpdateCollector 04/08/20 15:11:26 Getting monitoring info for pid 639929 04/08/20 15:15:26 enter Matchmaker::updateCollector 04/08/20 15:15:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:15:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:15:26 exit Matchmaker::UpdateCollector 04/08/20 15:15:26 Getting monitoring info for pid 639929 04/08/20 15:19:26 Getting monitoring info for pid 639929 04/08/20 15:20:26 enter Matchmaker::updateCollector 04/08/20 15:20:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:20:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:20:26 exit Matchmaker::UpdateCollector 04/08/20 15:23:26 Getting monitoring info for pid 639929 04/08/20 15:25:26 enter Matchmaker::updateCollector 04/08/20 15:25:26 Trying to update collector <10.20.60.65:9618> 04/08/20 15:25:26 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 15:25:26 exit Matchmaker::UpdateCollector 04/08/20 15:27:23 DaemonKeepAlive: in SendAliveToParent() 04/08/20 15:27:23 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 15:27:23 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 639885_7712 04/08/20 15:27:23 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 15:27:26 Getting monitoring info for pid 639929
04/08/20 11:16:33 ---------- Started Negotiation Cycle ---------- 04/08/20 11:16:33 Phase 1: Obtaining ads from collector ... 04/08/20 11:16:33 Getting startd private ads ... 04/08/20 11:16:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:16:33 Getting Scheduler, Submitter and Machine ads ... 04/08/20 11:16:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:16:33 Sorting 8 ads ... 04/08/20 11:16:33 Got ads: 8 public and 5 private 04/08/20 11:16:33 Public ads include 2 submitter, 5 startd 04/08/20 11:16:33 Phase 2: Performing accounting ... 04/08/20 11:16:33 Entering compute_significant_attrs() 04/08/20 11:16:33 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 11:16:33 Phase 3: Sorting submitter ads by priority ... 04/08/20 11:16:33 Starting prefetch round; 2 potential prefetches to do. 04/08/20 11:16:33 Assigned 1 units of work for prefetching. 04/08/20 11:16:33 Starting prefetch loop. 04/08/20 11:16:33 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 11:16:33 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:16:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:16:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Prefetch negotiation would block. 04/08/20 11:16:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:16:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:16:33 Assigned 1 units of work for prefetching. 04/08/20 11:16:33 Starting prefetch loop. 04/08/20 11:16:33 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 11:16:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:16:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:16:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Prefetch negotiation would block. 04/08/20 11:16:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Assigned 0 units of work for prefetching. 04/08/20 11:16:33 Starting prefetch loop. 04/08/20 11:16:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:16:33 Getting reply from schedd ... 04/08/20 11:16:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:16:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:16:33 Assigned 0 units of work for prefetching. 04/08/20 11:16:33 Prefetch summary: 2 attempted, 2 successful. 04/08/20 11:16:33 Phase 4.1: Negotiating with schedds ... 04/08/20 11:16:33 numSlots = 5 (after trimming=5) 04/08/20 11:16:33 slotWeightTotal = 4.000000 04/08/20 11:16:33 minSlotWeight = 0.000000 04/08/20 11:16:33 pieLeft = 3.728 04/08/20 11:16:33 NormalFactor = 14.684835 04/08/20 11:16:33 MaxPrioValue = 15321.830078 04/08/20 11:16:33 NumSubmitterAds = 2 04/08/20 11:16:33 Negotiating with prod.atlascondor@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4> 04/08/20 11:16:33 0 seconds so far for this submitter 04/08/20 11:16:33 0 seconds so far for this schedd 04/08/20 11:16:33 Calculating submitter limit with the following parameters 04/08/20 11:16:33 SubmitterPrio = 1119.621094 04/08/20 11:16:33 SubmitterPrioFactor = 1000.000000 04/08/20 11:16:33 submitterShare = 0.931903 04/08/20 11:16:33 submitterAbsShare = 0.909091 04/08/20 11:16:33 submitterLimit = 3.727610 04/08/20 11:16:33 submitterUsage = 0.000000 04/08/20 11:16:33 Using resource request list from cache. 04/08/20 11:16:33 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:16:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:16:33 Request 00020.00000: autocluster 1 (request count 1 of 1) 04/08/20 11:16:33 matchmakingAlgorithm: limit 3.727610 used 0.000000 pieLeft 3.727610 04/08/20 11:16:33 Classad debug: [0.00095ms] RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00191ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01597ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01407ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.07796ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.03290ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.21291ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01407ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01192ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.08202ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.19193ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: [0.00095ms] 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01502ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01311ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.06914ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: [0.00095ms] 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01383ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.15187ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01407ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.02909ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.08416ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01287ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.17905ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Request 00020.00001: autocluster 3 (request count 1 of 1) 04/08/20 11:16:33 matchmakingAlgorithm: limit 3.727610 used 0.000000 pieLeft 3.727610 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01311ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01192ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.06700ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: [0.00119ms] 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01407ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.15092ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: [0.00095ms] RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01311ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.00095ms] time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01311ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.08106ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.17977ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01597ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01383ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.08798ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01311ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.16594ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Classad debug: RemoteUserPrio --> 15321.8 04/08/20 11:16:33 Classad debug: [0.00095ms] SubmitterUserPrio --> 1119.62 04/08/20 11:16:33 Classad debug: 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01311ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: time() --> 1586344593 04/08/20 11:16:33 Classad debug: [0.00095ms] 1586330049 --> 1586330049 04/08/20 11:16:33 Classad debug: [0.01407ms] JobStart --> 1586330049 04/08/20 11:16:33 Classad debug: [0.08607ms] ifThenElse(JobStart isnt undefined,(time() - JobStart),0) --> 14544 04/08/20 11:16:33 Classad debug: 1 --> 1 04/08/20 11:16:33 Classad debug: [0.01287ms] MinRunTimeHours --> 1 04/08/20 11:16:33 Classad debug: [0.16403ms] ((RemoteUserPrio > SubmitterUserPrio * 1.200000000000000E+00) && ((ifThenElse(JobStart isnt undefined,(time() - JobStart),0)) > MinRunTimeHours * 60)) || (Target.RequestGPUs > 0 && My.RequestGPUs isnt 0 && My.TotalGPUs isnt 0) --> TRUE 04/08/20 11:16:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:16:33 Submitter prod.atlascondor@atlas.local got all it wants; removing it. 04/08/20 11:16:33 resources used by prod.atlascondor@atlas.local are 0.000000 04/08/20 11:16:33 Negotiating with prod.fehrmann@atlas.local skipped because no idle jobs 04/08/20 11:16:33 Submitter prod.fehrmann@atlas.local got all it wants; removing it. 04/08/20 11:16:33 resources used by prod.fehrmann@atlas.local are 4.000000 04/08/20 11:16:33 resources used scheddUsed= 4.000000 04/08/20 11:16:33 negotiateWithGroup resources used submitterAds length 0 04/08/20 11:16:33 ---------- Finished Negotiation Cycle ---------- 04/08/20 11:16:33 Updating collector with accounting information 04/08/20 11:16:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:16:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:16:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:16:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:16:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:16:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:16:33 Done Updating collector with accounting information 04/08/20 11:17:31 enter Matchmaker::updateCollector 04/08/20 11:17:31 Trying to update collector <10.20.60.65:9618> 04/08/20 11:17:31 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:17:31 exit Matchmaker::UpdateCollector 04/08/20 11:17:31 Getting monitoring info for pid 636339 04/08/20 11:17:33 ---------- Started Negotiation Cycle ---------- 04/08/20 11:17:33 Phase 1: Obtaining ads from collector ... 04/08/20 11:17:33 Getting startd private ads ... 04/08/20 11:17:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:17:33 Getting Scheduler, Submitter and Machine ads ... 04/08/20 11:17:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:17:33 Sorting 4 ads ... 04/08/20 11:17:33 Got ads: 4 public and 1 private 04/08/20 11:17:33 Public ads include 2 submitter, 1 startd 04/08/20 11:17:33 Phase 2: Performing accounting ... 04/08/20 11:17:33 Entering compute_significant_attrs() 04/08/20 11:17:33 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobStart,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 11:17:33 Phase 3: Sorting submitter ads by priority ... 04/08/20 11:17:33 Starting prefetch round; 2 potential prefetches to do. 04/08/20 11:17:33 Assigned 1 units of work for prefetching. 04/08/20 11:17:33 Starting prefetch loop. 04/08/20 11:17:33 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 11:17:33 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:17:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:17:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Prefetch negotiation would block. 04/08/20 11:17:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:17:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:17:33 Assigned 1 units of work for prefetching. 04/08/20 11:17:33 Starting prefetch loop. 04/08/20 11:17:33 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 11:17:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:17:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:17:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Prefetch negotiation would block. 04/08/20 11:17:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:17:33 Getting reply from schedd ... 04/08/20 11:17:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:17:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:17:33 Assigned 0 units of work for prefetching. 04/08/20 11:17:33 Prefetch summary: 2 attempted, 2 successful. 04/08/20 11:17:33 Phase 4.1: Negotiating with schedds ... 04/08/20 11:17:33 numSlots = 1 (after trimming=1) 04/08/20 11:17:33 slotWeightTotal = 4.000000 04/08/20 11:17:33 minSlotWeight = 4.000000 04/08/20 11:17:33 pieLeft = 4.000 04/08/20 11:17:33 NormalFactor = 14.702043 04/08/20 11:17:33 MaxPrioValue = 15333.709961 04/08/20 11:17:33 NumSubmitterAds = 2 04/08/20 11:17:33 Negotiating with prod.atlascondor@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4> 04/08/20 11:17:33 0 seconds so far for this submitter 04/08/20 11:17:33 0 seconds so far for this schedd 04/08/20 11:17:33 Calculating submitter limit with the following parameters 04/08/20 11:17:33 SubmitterPrio = 1119.082031 04/08/20 11:17:33 SubmitterPrioFactor = 1000.000000 04/08/20 11:17:33 submitterShare = 0.931982 04/08/20 11:17:33 submitterAbsShare = 0.909091 04/08/20 11:17:33 submitterLimit = 3.727929 04/08/20 11:17:33 submitterUsage = 0.000000 04/08/20 11:17:33 Using resource request list from cache. 04/08/20 11:17:33 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:17:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:17:33 Request 00020.00000: autocluster 1 (request count 1 of 1) 04/08/20 11:17:33 matchmakingAlgorithm: limit 3.727929 used 0.000000 pieLeft 4.000000 04/08/20 11:17:33 Sending PERMISSION, claim id, startdAd to schedd 04/08/20 11:17:33 Notifying the accountant 04/08/20 11:17:33 Successfully matched with slot1@a3305.atlas.local 04/08/20 11:17:33 Match completed, match cost= 4 04/08/20 11:17:33 Over submitter resource limit (3.727929, used 4.000000) ... only consider startd ranks 04/08/20 11:17:33 Request 00020.00001: autocluster 3 (request count 1 of 1) 04/08/20 11:17:33 matchmakingAlgorithm: limit 3.727929 used 4.000000 pieLeft 0.000000 04/08/20 11:17:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:17:33 This submitter hit its submitterLimit. 04/08/20 11:17:33 Negotiating with prod.fehrmann@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4> 04/08/20 11:17:33 0 seconds so far for this submitter 04/08/20 11:17:33 0 seconds so far for this schedd 04/08/20 11:17:33 Calculating submitter limit with the following parameters 04/08/20 11:17:33 SubmitterPrio = 15333.709961 04/08/20 11:17:33 SubmitterPrioFactor = 10000.000000 04/08/20 11:17:33 submitterShare = 0.068018 04/08/20 11:17:33 submitterAbsShare = 0.090909 04/08/20 11:17:33 submitterLimit = 0.000000 (starved 0.272071) 04/08/20 11:17:33 submitterUsage = 0.000000 04/08/20 11:17:33 Using resource request list from cache. 04/08/20 11:17:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:17:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:17:33 Over submitter resource limit (0.000000, used 0.000000) ... only consider startd ranks 04/08/20 11:17:33 Request 00021.00000: autocluster 1 (request count 1 of 1) 04/08/20 11:17:33 matchmakingAlgorithm: limit 0.000000 used 0.000000 pieLeft 0.000000 04/08/20 11:17:33 Request 00021.00001: autocluster 2 (request count 1 of 1) 04/08/20 11:17:33 matchmakingAlgorithm: limit 0.000000 used 0.000000 pieLeft 0.000000 04/08/20 11:17:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:17:33 This submitter hit its submitterLimit. 04/08/20 11:17:33 resources used scheddUsed= 4.000000 04/08/20 11:17:33 negotiateWithGroup resources used submitterAds length 2 04/08/20 11:17:33 ---------- Finished Negotiation Cycle ---------- 04/08/20 11:17:33 Updating collector with accounting information 04/08/20 11:17:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:17:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:17:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:17:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:17:33 Trying to update collector <10.20.60.65:9618> 04/08/20 11:17:33 Attempting to send update via TCP to collector condorhubtest.atlas.local <10.20.60.65:9618> 04/08/20 11:17:33 Done Updating collector with accounting information 04/08/20 11:17:43 DaemonKeepAlive: in SendAliveToParent() 04/08/20 11:17:43 DaemonKeepAlive: Leaving SendAliveToParent() - pending 04/08/20 11:17:43 SharedPortClient: sent connection request to daemon at <10.20.60.65:9618> for shared port id 636293_a6e2 04/08/20 11:17:43 Completed DC_CHILDALIVE to daemon at <10.20.60.65:9618> 04/08/20 11:18:33 ---------- Started Negotiation Cycle ---------- 04/08/20 11:18:33 Phase 1: Obtaining ads from collector ... 04/08/20 11:18:33 Getting startd private ads ... 04/08/20 11:18:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:18:33 Getting Scheduler, Submitter and Machine ads ... 04/08/20 11:18:33 Trying to query collector <10.20.60.65:9618> 04/08/20 11:18:33 Sorting 6 ads ... 04/08/20 11:18:33 Got ads: 6 public and 3 private 04/08/20 11:18:33 Public ads include 2 submitter, 3 startd 04/08/20 11:18:33 Phase 2: Performing accounting ... 04/08/20 11:18:33 Entering compute_significant_attrs() 04/08/20 11:18:33 Leaving compute_significant_attrs() - result=_condor_RequestCpus,_condor_RequestDisk,_condor_RequestMemory,JobUniverse,LastCheckpointPlatform,MachineLastMatchTime,NumCkpts,RequestCpus,RequestDisk,RequestGPUs,RequestMemory,TotalGPUs 04/08/20 11:18:33 Phase 3: Sorting submitter ads by priority ... 04/08/20 11:18:33 Starting prefetch round; 2 potential prefetches to do. 04/08/20 11:18:33 Assigned 1 units of work for prefetching. 04/08/20 11:18:33 Starting prefetch loop. 04/08/20 11:18:33 Starting prefetch negotiation for prod.atlascondor@atlas.local. 04/08/20 11:18:33 Socket to prod.atlascondor@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:18:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:18:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:18:33 Prefetch negotiation immediately finished. 04/08/20 11:18:33 Assigned 1 units of work for prefetching. 04/08/20 11:18:33 Starting prefetch loop. 04/08/20 11:18:33 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 11:18:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:18:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:18:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Prefetch negotiation would block. 04/08/20 11:18:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:18:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:18:33 Assigned 0 units of work for prefetching. 04/08/20 11:18:33 Prefetch summary: 2 attempted, 2 successful. 04/08/20 11:18:33 Phase 4.1: Negotiating with schedds ... 04/08/20 11:18:33 numSlots = 3 (after trimming=3) 04/08/20 11:18:33 slotWeightTotal = 4.000000 04/08/20 11:18:33 minSlotWeight = 1.000000 04/08/20 11:18:33 pieLeft = 2.000 04/08/20 11:18:33 NormalFactor = 14.678507 04/08/20 11:18:33 MaxPrioValue = 15326.329102 04/08/20 11:18:33 NumSubmitterAds = 2 04/08/20 11:18:33 Negotiating with prod.atlascondor@atlas.local skipped because no idle jobs 04/08/20 11:18:33 Submitter prod.atlascondor@atlas.local got all it wants; removing it. 04/08/20 11:18:33 resources used by prod.atlascondor@atlas.local are 2.000000 04/08/20 11:18:33 Negotiating with prod.fehrmann@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4> 04/08/20 11:18:33 0 seconds so far for this submitter 04/08/20 11:18:33 0 seconds so far for this schedd 04/08/20 11:18:33 Calculating submitter limit with the following parameters 04/08/20 11:18:33 SubmitterPrio = 15326.329102 04/08/20 11:18:33 SubmitterPrioFactor = 10000.000000 04/08/20 11:18:33 submitterShare = 0.068127 04/08/20 11:18:33 submitterAbsShare = 0.090909 04/08/20 11:18:33 submitterLimit = 0.272507 04/08/20 11:18:33 submitterUsage = 0.000000 04/08/20 11:18:33 Using resource request list from cache. 04/08/20 11:18:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:18:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:18:33 Request 00021.00000: autocluster 1 (request count 1 of 1) 04/08/20 11:18:33 matchmakingAlgorithm: limit 0.272507 used 0.000000 pieLeft 2.000000 04/08/20 11:18:33 Sending PERMISSION, claim id, startdAd to schedd 04/08/20 11:18:33 Notifying the accountant 04/08/20 11:18:33 Successfully matched with slot1@a3305.atlas.local 04/08/20 11:18:33 Match completed, match cost= 2 04/08/20 11:18:33 Over submitter resource limit (0.272507, used 2.000000) ... only consider startd ranks 04/08/20 11:18:33 Request 00021.00001: autocluster 2 (request count 1 of 1) 04/08/20 11:18:33 matchmakingAlgorithm: limit 0.272507 used 2.000000 pieLeft -0.000000 04/08/20 11:18:33 Request 00021.00002: autocluster 1 (request count 1 of 2) 04/08/20 11:18:33 matchmakingAlgorithm: limit 0.272507 used 2.000000 pieLeft -0.000000 04/08/20 11:18:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:18:33 This submitter hit its submitterLimit. 04/08/20 11:18:33 resources used scheddUsed= 4.000000 04/08/20 11:18:33 Starting prefetch round; 1 potential prefetches to do. 04/08/20 11:18:33 Assigned 1 units of work for prefetching. 04/08/20 11:18:33 Starting prefetch loop. 04/08/20 11:18:33 Starting prefetch negotiation for prod.fehrmann@atlas.local. 04/08/20 11:18:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:18:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:18:33 Sending SEND_RESOURCE_REQUEST_LIST/200/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Prefetch negotiation would block. 04/08/20 11:18:33 Waiting on the results of 1 negotiation sessions. 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got JOB_INFO command; getting classad/eom 04/08/20 11:18:33 Getting reply from schedd ... 04/08/20 11:18:33 Got NO_MORE_JOBS; schedd has no more requests 04/08/20 11:18:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:18:33 Assigned 0 units of work for prefetching. 04/08/20 11:18:33 Prefetch summary: 1 attempted, 1 successful. 04/08/20 11:18:33 Phase 4.2: Negotiating with schedds ... 04/08/20 11:18:33 numSlots = 3 (after trimming=2) 04/08/20 11:18:33 slotWeightTotal = 4.000000 04/08/20 11:18:33 minSlotWeight = 1.000000 04/08/20 11:18:33 pieLeft = 2.000 04/08/20 11:18:33 NormalFactor = 1.000000 04/08/20 11:18:33 MaxPrioValue = 15326.329102 04/08/20 11:18:33 NumSubmitterAds = 1 04/08/20 11:18:33 Negotiating with prod.fehrmann@atlas.local at <10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4> 04/08/20 11:18:33 0 seconds so far for this submitter 04/08/20 11:18:33 0 seconds so far for this schedd 04/08/20 11:18:33 Calculating submitter limit with the following parameters 04/08/20 11:18:33 SubmitterPrio = 15326.329102 04/08/20 11:18:33 SubmitterPrioFactor = 10000.000000 04/08/20 11:18:33 submitterShare = 1.000000 04/08/20 11:18:33 submitterAbsShare = 1.000000 04/08/20 11:18:33 submitterLimit = 2.000000 04/08/20 11:18:33 submitterUsage = 2.000000 04/08/20 11:18:33 Using resource request list from cache. 04/08/20 11:18:33 Socket to prod.fehrmann@atlas.local (<10.20.60.65:9618?addrs=10.20.60.65-9618&noUDP&sock=636293_a6e2_4>) already in cache, reusing 04/08/20 11:18:33 Started NEGOTIATE with remote schedd; protocol version 1. 04/08/20 11:18:33 Request 00021.00001: autocluster 2 (request count 1 of 1) 04/08/20 11:18:33 matchmakingAlgorithm: limit 2.000000 used 0.000000 pieLeft 2.000000 04/08/20 11:18:33 Request 00021.00002: autocluster 1 (request count 1 of 2) 04/08/20 11:18:33 matchmakingAlgorithm: limit 2.000000 used 0.000000 pieLeft 2.000000 04/08/20 11:18:33 Send END_NEGOTIATE to remote schedd 04/08/20 11:18:33 Submitter prod.fehrmann@atlas.local got all it wants; removing it. 04/08/20 11:18:33 resources used by prod.fehrmann@atlas.local are 2.000000 04/08/20 11:18:33 resources used scheddUsed= 6.000000 04/08/20 11:18:33 negotiateWithGroup resources used submitterAds length 0 04/08/20 11:18:33 ---------- Finished Negotiation Cycle ----------
