diff --git a/cuebot/src/main/java/com/imageworks/spcue/DispatchFrame.java b/cuebot/src/main/java/com/imageworks/spcue/DispatchFrame.java index b73cd75c3c..f1ce21070f 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/DispatchFrame.java +++ b/cuebot/src/main/java/com/imageworks/spcue/DispatchFrame.java @@ -71,4 +71,7 @@ public long getMinMemory() { // Parameters to tell rqd whether or not to use Loki for frame logs and which base url to use public String lokiURL; + + // Minutes without progress before RQD kills this frame as stuck. 0 = disabled. + public int stuckDetectionLlu; } diff --git a/cuebot/src/main/java/com/imageworks/spcue/LayerDetail.java b/cuebot/src/main/java/com/imageworks/spcue/LayerDetail.java index 47f3ad59cd..e2d97f486e 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/LayerDetail.java +++ b/cuebot/src/main/java/com/imageworks/spcue/LayerDetail.java @@ -37,6 +37,7 @@ public class LayerDetail extends LayerEntity implements LayerInterface { public int chunkSize; public int timeout; public int timeout_llu; + public int stuck_detection_llu; public int dispatchOrder; public int totalFrameCount; @@ -112,6 +113,14 @@ public void setTimeoutLLU(int timeout_llu) { this.timeout_llu = timeout_llu; } + public int getStuckDetectionLLU() { + return stuck_detection_llu; + } + + public void setStuckDetectionLLU(int stuck_detection_llu) { + this.stuck_detection_llu = stuck_detection_llu; + } + public long getMinimumMemory() { return minimumMemory; } diff --git a/cuebot/src/main/java/com/imageworks/spcue/ServiceEntity.java b/cuebot/src/main/java/com/imageworks/spcue/ServiceEntity.java index 74570c605c..b0662af924 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/ServiceEntity.java +++ b/cuebot/src/main/java/com/imageworks/spcue/ServiceEntity.java @@ -64,6 +64,12 @@ public class ServiceEntity extends Entity { public int timeout_llu = 0; + /** + * Minutes without progress (log, CPU, or IO) before RQD kills a frame as stuck. 0 disables + * stuck detection. + */ + public int stuck_detection_llu = 0; + public long minMemoryIncrease = Dispatcher.MINIMUM_MEMORY_INCREASE; } diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/LayerDao.java b/cuebot/src/main/java/com/imageworks/spcue/dao/LayerDao.java index 59f09d0c08..18abe640b6 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/LayerDao.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/LayerDao.java @@ -332,6 +332,15 @@ public interface LayerDao { */ void updateTimeoutLLU(LayerInterface layer, int timeout_llu); + /** + * Update stuck-detection LLU (minutes without progress before RQD kills a frame as stuck) for + * the given layer. 0 disables stuck detection. + * + * @param layer + * @param stuck_detection_llu + */ + void updateStuckDetectionLLU(LayerInterface layer, int stuck_detection_llu); + /** * Authoritatively set or clear the layer's start-after gate. No frame of the layer may start * before the given time. A null timestamp clears the gate. diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/DispatchQuery.java b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/DispatchQuery.java index 34d04bac13..969a769a5a 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/DispatchQuery.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/DispatchQuery.java @@ -545,7 +545,8 @@ private static final String replaceQueryForFifo(String query) { + "str_cmd, " + "str_range, " + "int_chunk_size, " - + "str_services "; + + "str_services, " + + "int_stuck_detection_llu "; // spotless:on /** @@ -590,7 +591,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -682,7 +684,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -775,7 +778,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -861,7 +865,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -950,7 +955,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -1042,7 +1048,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -1135,7 +1142,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " @@ -1221,7 +1229,8 @@ private static final String replaceQueryForFifo(String query) { + "layer.str_cmd, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "job, " + "frame, " diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/FrameDaoJdbc.java b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/FrameDaoJdbc.java index c79542107e..fb016e8418 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/FrameDaoJdbc.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/FrameDaoJdbc.java @@ -361,6 +361,7 @@ public DispatchFrame mapRow(ResultSet rs, int rowNum) throws SQLException { frame.services = rs.getString("str_services"); frame.os = rs.getString("str_os"); frame.lokiURL = rs.getString("str_loki_url"); + frame.stuckDetectionLlu = rs.getInt("int_stuck_detection_llu"); return frame; } }; @@ -398,7 +399,8 @@ public DispatchFrame mapRow(ResultSet rs, int rowNum) throws SQLException { + "layer.int_gpu_mem_min, " + "layer.str_range, " + "layer.int_chunk_size, " - + "layer.str_services " + + "layer.str_services, " + + "layer.int_stuck_detection_llu " + "FROM " + "layer, " + "job, " diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/LayerDaoJdbc.java b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/LayerDaoJdbc.java index 0556a03a50..32fdf83623 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/LayerDaoJdbc.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/LayerDaoJdbc.java @@ -222,6 +222,7 @@ public LayerDetail mapRow(ResultSet rs, int rowNum) throws SQLException { layer.services.addAll(Lists.newArrayList(rs.getString("str_services").split(","))); layer.timeout = rs.getInt("int_timeout"); layer.timeout_llu = rs.getInt("int_timeout_llu"); + layer.stuck_detection_llu = rs.getInt("int_stuck_detection_llu"); layer.startAfter = rs.getTimestamp("ts_start_after"); layer.startAfterReason = rs.getString("str_start_after_reason"); return layer; @@ -324,9 +325,10 @@ public LayerInterface getLayer(String id) { + "int_gpu_mem_min, " + "str_services, " + "int_timeout," - + "int_timeout_llu " + + "int_timeout_llu, " + + "int_stuck_detection_llu " + ") " - + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)"; + + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)"; // spotless:on @Override @@ -336,7 +338,7 @@ public void insertLayerDetail(LayerDetail l) { l.chunkSize, l.dispatchOrder, StringUtils.join(l.tags, " | "), l.type.toString(), l.minimumCores, l.maximumCores, l.isThreadable, l.minimumMemory, l.minimumGpus, l.maximumGpus, l.minimumGpuMemory, StringUtils.join(l.services, ","), l.timeout, - l.timeout_llu); + l.timeout_llu, l.stuck_detection_llu); } @Override @@ -706,6 +708,12 @@ public void updateTimeoutLLU(LayerInterface layer, int timeout_llu) { layer.getLayerId()); } + @Override + public void updateStuckDetectionLLU(LayerInterface layer, int stuck_detection_llu) { + getJdbcTemplate().update("UPDATE layer SET int_stuck_detection_llu=? WHERE pk_layer=?", + stuck_detection_llu, layer.getLayerId()); + } + @Override public void updateStartAfter(LayerInterface layer, Timestamp startAfter, String reason) { if (startAfter == null) { diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/ServiceDaoJdbc.java b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/ServiceDaoJdbc.java index db635fd048..9e6c9db75a 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/ServiceDaoJdbc.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/ServiceDaoJdbc.java @@ -62,6 +62,7 @@ public ServiceEntity mapRow(ResultSet rs, int rowNum) throws SQLException { s.tags = splitTags(rs.getString("str_tags")); s.timeout = rs.getInt("int_timeout"); s.timeout_llu = rs.getInt("int_timeout_llu"); + s.stuck_detection_llu = rs.getInt("int_stuck_detection_llu"); s.minMemoryIncrease = rs.getLong("int_min_memory_increase"); return s; } @@ -84,6 +85,7 @@ public ServiceOverrideEntity mapRow(ResultSet rs, int rowNum) throws SQLExceptio s.showId = rs.getString("pk_show"); s.timeout = rs.getInt("int_timeout"); s.timeout_llu = rs.getInt("int_timeout_llu"); + s.stuck_detection_llu = rs.getInt("int_stuck_detection_llu"); s.minMemoryIncrease = rs.getLong("int_min_memory_increase"); return s; } @@ -104,6 +106,7 @@ public ServiceOverrideEntity mapRow(ResultSet rs, int rowNum) throws SQLExceptio + "service.str_tags, " + "service.int_timeout, " + "service.int_timeout_llu, " + + "service.int_stuck_detection_llu, " + "service.int_min_memory_increase " + "FROM " + "service "; @@ -130,6 +133,7 @@ public ServiceEntity get(String id) { + "show_service.str_tags," + "show_service.int_timeout," + "show_service.int_timeout_llu," + + "show_service.int_stuck_detection_llu," + "show_service.int_min_memory_increase," + "show.pk_show " + "FROM " @@ -179,9 +183,10 @@ public boolean isOverridden(String service, String show) { + "str_tags," + "int_timeout," + "int_timeout_llu, " + + "int_stuck_detection_llu, " + "int_min_memory_increase " + ") " - + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?)"; + + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?)"; // spotless:on @Override @@ -191,7 +196,7 @@ public void insert(ServiceEntity service) { service.minCores, service.maxCores, service.minMemory, service.minGpus, service.maxGpus, service.minGpuMemory, StringUtils.join(service.tags.toArray(), " | "), service.timeout, - service.timeout_llu, service.minMemoryIncrease); + service.timeout_llu, service.stuck_detection_llu, service.minMemoryIncrease); } // spotless:off @@ -210,9 +215,10 @@ public void insert(ServiceEntity service) { + "str_tags," + "int_timeout," + "int_timeout_llu, " + + "int_stuck_detection_llu, " + "int_min_memory_increase " + ") " - + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?)"; + + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)"; // spotless:on @Override @@ -221,7 +227,8 @@ public void insert(ServiceOverrideEntity service) { getJdbcTemplate().update(INSERT_SERVICE_WITH_SHOW, service.id, service.showId, service.name, service.threadable, service.minCores, service.maxCores, service.minMemory, service.minGpus, service.maxGpus, service.minGpuMemory, joinTags(service.tags), - service.timeout, service.timeout_llu, service.minMemoryIncrease); + service.timeout, service.timeout_llu, service.stuck_detection_llu, + service.minMemoryIncrease); } // spotless:off @@ -240,6 +247,7 @@ service.minGpus, service.maxGpus, service.minGpuMemory, joinTags(service.tags), + "str_tags=?," + "int_timeout=?," + "int_timeout_llu=?, " + + "int_stuck_detection_llu=?, " + "int_min_memory_increase=? " + "WHERE " + "pk_service = ?"; @@ -250,7 +258,7 @@ public void update(ServiceEntity service) { getJdbcTemplate().update(UPDATE_SERVICE, service.name, service.threadable, service.minCores, service.maxCores, service.minMemory, service.minGpus, service.maxGpus, service.minGpuMemory, joinTags(service.tags), service.timeout, service.timeout_llu, - service.minMemoryIncrease, service.getId()); + service.stuck_detection_llu, service.minMemoryIncrease, service.getId()); } // spotless:off @@ -269,6 +277,7 @@ service.minGpuMemory, joinTags(service.tags), service.timeout, service.timeout_l + "str_tags=?," + "int_timeout=?," + "int_timeout_llu=?, " + + "int_stuck_detection_llu=?, " + "int_min_memory_increase=? " + "WHERE " + "pk_show_service = ?"; @@ -279,7 +288,8 @@ public void update(ServiceOverrideEntity service) { getJdbcTemplate().update(UPDATE_SERVICE_WITH_SHOW, service.name, service.threadable, service.minCores, service.maxCores, service.minMemory, service.minGpus, service.maxGpus, service.minGpuMemory, joinTags(service.tags), service.timeout, - service.timeout_llu, service.minMemoryIncrease, service.getId()); + service.timeout_llu, service.stuck_detection_llu, service.minMemoryIncrease, + service.getId()); } @Override diff --git a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/WhiteboardDaoJdbc.java b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/WhiteboardDaoJdbc.java index bdd8b7f98d..f0427d7867 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/WhiteboardDaoJdbc.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dao/postgres/WhiteboardDaoJdbc.java @@ -1202,6 +1202,7 @@ public Layer mapRow(ResultSet rs, int rowNum) throws SQLException { .setMemoryOptimizerEnabled(rs.getBoolean("b_optimize")) .setTimeout(rs.getInt("int_timeout")) .setTimeoutLlu(rs.getInt("int_timeout_llu")) + .setStuckDetectionLlu(rs.getInt("int_stuck_detection_llu")) // layer.ts_eligible is NOT NULL by schema (defaults to layer creation time), so // no submission-time fallback is needed. .setEligibleTime(getEligibleTimeInEpoch(rs, null)); @@ -1443,6 +1444,7 @@ public Service mapRow(ResultSet rs, int rowNum) throws SQLException { ServiceDaoJdbc.splitTags(SqlUtil.getString(rs, "str_tags")))) .setTimeout(rs.getInt("int_timeout")) .setTimeoutLlu(rs.getInt("int_timeout_llu")) + .setStuckDetectionLlu(rs.getInt("int_stuck_detection_llu")) .setMinMemoryIncrease(rs.getInt("int_min_memory_increase")).build(); } }; @@ -1464,6 +1466,7 @@ public ServiceOverride mapRow(ResultSet rs, int rowNum) throws SQLException { ServiceDaoJdbc.splitTags(SqlUtil.getString(rs, "str_tags")))) .setTimeout(rs.getInt("int_timeout")) .setTimeoutLlu(rs.getInt("int_timeout_llu")) + .setStuckDetectionLlu(rs.getInt("int_stuck_detection_llu")) .setMinMemoryIncrease(rs.getInt("int_min_memory_increase")).build(); return ServiceOverride.newBuilder() .setId(SqlUtil.getString(rs, "pk_show_service")).setData(data).build(); @@ -2158,6 +2161,7 @@ public Show mapRow(ResultSet rs, int rowNum) throws SQLException { + "service.str_tags," + "service.int_timeout," + "service.int_timeout_llu," + + "service.int_stuck_detection_llu," + "service.int_min_memory_increase " + "FROM " + "service "; @@ -2178,6 +2182,7 @@ public Show mapRow(ResultSet rs, int rowNum) throws SQLException { + "show_service.str_tags," + "show_service.int_timeout," + "show_service.int_timeout_llu," + + "show_service.int_stuck_detection_llu," + "show_service.int_min_memory_increase " + "FROM " + "show_service, " diff --git a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/DispatchSupportService.java b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/DispatchSupportService.java index 0c164c1cc9..72f0b6d002 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/DispatchSupportService.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/DispatchSupportService.java @@ -444,6 +444,7 @@ public RunFrame prepareRqdRunFrame(VirtualProc proc, DispatchFrame frame) { .setNumCores(proc.coresReserved).setNumGpus(proc.gpusReserved) .setStartTime(System.currentTimeMillis()).setIgnoreNimby(proc.isLocalDispatch) .setOs(proc.os).setSoftMemoryLimit(frame.softMemoryLimit).setLokiUrl(frame.lokiURL) + .setStuckDetectionLlu(frame.stuckDetectionLlu) .setHardMemoryLimit(frame.hardMemoryLimit) .putAllEnvironment(jobDao.getEnvironment(frame)) .putAllEnvironment(layerDao.getLayerEnvironment(frame)).putEnvironment("CUE3", "1") diff --git a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/Dispatcher.java b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/Dispatcher.java index 634502625c..8383b19e7d 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/Dispatcher.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/Dispatcher.java @@ -71,6 +71,12 @@ public interface Dispatcher { */ public static final int EXIT_STATUS_FAILED_KILL = 302; + /* + * RQD killed the frame after detecting no progress (log, CPU, or IO) for longer than the + * layer's stuck-detection threshold. + */ + public static final int EXIT_STATUS_FRAME_STUCK = 303; + // Return value for cleared frame public static final int EXIT_STATUS_DOWN_HOST = 399; diff --git a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/FrameCompleteHandler.java b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/FrameCompleteHandler.java index da0e563b03..37c164b928 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/dispatcher/FrameCompleteHandler.java +++ b/cuebot/src/main/java/com/imageworks/spcue/dispatcher/FrameCompleteHandler.java @@ -979,6 +979,14 @@ public static final FrameState determineFrameState(DispatchJob job, LayerDetail return FrameState.WAITING; } + // RQD killed the frame as stuck (no log/CPU/IO progress). The hang is usually + // host-local, so retry on another host rather than letting the stale-LLU check below + // mark the frame DEAD on its first strike. + if (report.getExitStatus() == Dispatcher.EXIT_STATUS_FRAME_STUCK + && frame.retries < job.maxRetries) { + return FrameState.WAITING; + } + // Log update (LLU) and run time timeouts. long minutesSinceLogUpdate = (System.currentTimeMillis() / 1000 - report.getFrame().getLluTime()) / 60; diff --git a/cuebot/src/main/java/com/imageworks/spcue/monitoring/MonitoringEventBuilder.java b/cuebot/src/main/java/com/imageworks/spcue/monitoring/MonitoringEventBuilder.java index f39ef4547f..3c7b7344f1 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/monitoring/MonitoringEventBuilder.java +++ b/cuebot/src/main/java/com/imageworks/spcue/monitoring/MonitoringEventBuilder.java @@ -117,14 +117,14 @@ public LayerEvent buildLayerEvent(EventType eventType, LayerDetail layer, String EventHeader header = publisher.createEventHeader(eventType, layer.getJobId()).build(); // Build the embedded Layer message - Layer.Builder layerBuilder = - Layer.newBuilder().setId(layer.getLayerId()).setName(layer.getName()) - .setType(layer.type).setMinCores(layer.minimumCores / 100.0f) - .setMaxCores(layer.maximumCores / 100.0f).setMinGpus(layer.minimumGpus) - .setMaxGpus(layer.maximumGpus).setMinMemory(layer.minimumMemory) - .setMinGpuMemory(layer.minimumGpuMemory).setIsThreadable(layer.isThreadable) - .setChunkSize(layer.chunkSize).setTimeout(layer.timeout) - .setTimeoutLlu(layer.timeout_llu).setParentId(layer.getJobId()); + Layer.Builder layerBuilder = Layer.newBuilder().setId(layer.getLayerId()) + .setName(layer.getName()).setType(layer.type) + .setMinCores(layer.minimumCores / 100.0f).setMaxCores(layer.maximumCores / 100.0f) + .setMinGpus(layer.minimumGpus).setMaxGpus(layer.maximumGpus) + .setMinMemory(layer.minimumMemory).setMinGpuMemory(layer.minimumGpuMemory) + .setIsThreadable(layer.isThreadable).setChunkSize(layer.chunkSize) + .setTimeout(layer.timeout).setTimeoutLlu(layer.timeout_llu) + .setStuckDetectionLlu(layer.stuck_detection_llu).setParentId(layer.getJobId()); if (layer.tags != null && !layer.tags.isEmpty()) { layerBuilder.addAllTags(layer.tags); diff --git a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageLayer.java b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageLayer.java index 5d7b507182..6394ad9dac 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageLayer.java +++ b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageLayer.java @@ -113,6 +113,8 @@ import com.imageworks.spcue.grpc.job.LayerSetThreadableResponse; import com.imageworks.spcue.grpc.job.LayerSetTimeoutRequest; import com.imageworks.spcue.grpc.job.LayerSetTimeoutResponse; +import com.imageworks.spcue.grpc.job.LayerSetStuckDetectionLLURequest; +import com.imageworks.spcue.grpc.job.LayerSetStuckDetectionLLUResponse; import com.imageworks.spcue.grpc.job.LayerSetTimeoutLLURequest; import com.imageworks.spcue.grpc.job.LayerSetTimeoutLLUResponse; import com.imageworks.spcue.grpc.job.LayerStaggerFramesRequest; @@ -464,6 +466,17 @@ public void setTimeoutLLU(LayerSetTimeoutLLURequest request, } } + @Override + public void setStuckDetectionLLU(LayerSetStuckDetectionLLURequest request, + StreamObserver responseObserver) { + updateLayer(request.getLayer()); + if (attemptChange(env, property, jobManager, layer, responseObserver)) { + layerDao.updateStuckDetectionLLU(layer, request.getStuckDetectionLlu()); + responseObserver.onNext(LayerSetStuckDetectionLLUResponse.newBuilder().build()); + responseObserver.onCompleted(); + } + } + @Override public void setStartAfter(LayerSetStartAfterRequest request, StreamObserver responseObserver) { diff --git a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageService.java b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageService.java index b9f886fb30..8fd2331749 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageService.java +++ b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageService.java @@ -58,6 +58,7 @@ public void createService(ServiceCreateServiceRequest request, service.threadable = request.getData().getThreadable(); service.timeout = request.getData().getTimeout(); service.timeout_llu = request.getData().getTimeoutLlu(); + service.stuck_detection_llu = request.getData().getStuckDetectionLlu(); service.minMemoryIncrease = request.getData().getMinMemoryIncrease(); serviceManager.createService(service); responseObserver.onNext(ServiceCreateServiceResponse.newBuilder() @@ -132,6 +133,7 @@ private ServiceEntity toServiceEntity(Service service) { entity.threadable = service.getThreadable(); entity.timeout = service.getTimeout(); entity.timeout_llu = service.getTimeoutLlu(); + entity.stuck_detection_llu = service.getStuckDetectionLlu(); entity.minMemoryIncrease = service.getMinMemoryIncrease(); return entity; } diff --git a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageServiceOverride.java b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageServiceOverride.java index 05a02c122c..e147904677 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/servant/ManageServiceOverride.java +++ b/cuebot/src/main/java/com/imageworks/spcue/servant/ManageServiceOverride.java @@ -76,6 +76,7 @@ private ServiceOverrideEntity toServiceOverrideEntity(Service service, String sh entity.showId = showId; entity.timeout = service.getTimeout(); entity.timeout_llu = service.getTimeoutLlu(); + entity.stuck_detection_llu = service.getStuckDetectionLlu(); entity.minMemoryIncrease = service.getMinMemoryIncrease(); return entity; } diff --git a/cuebot/src/main/java/com/imageworks/spcue/service/JobSpec.java b/cuebot/src/main/java/com/imageworks/spcue/service/JobSpec.java index d4ff4e6b5d..54d1bbd490 100644 --- a/cuebot/src/main/java/com/imageworks/spcue/service/JobSpec.java +++ b/cuebot/src/main/java/com/imageworks/spcue/service/JobSpec.java @@ -444,6 +444,11 @@ private void handleLayerTags(BuildableJob buildableJob, Element jobTag) { layer.timeout_llu = Integer.parseInt(layerTag.getChildTextTrim("timeout_llu")); } + if (layerTag.getChildTextTrim("stuck_detection_llu") != null) { + layer.stuck_detection_llu = + Integer.parseInt(layerTag.getChildTextTrim("stuck_detection_llu")); + } + /* * Handle the layer environment */ @@ -728,6 +733,7 @@ private void determineResourceDefaults(Element layerTag, BuildableJob job, Layer layer.limits.addAll(limits); layer.timeout = primaryService.timeout; layer.timeout_llu = primaryService.timeout_llu; + layer.stuck_detection_llu = primaryService.stuck_detection_llu; } private void determineOutputs(Element layerTag, BuildableJob job, LayerDetail layer) { diff --git a/cuebot/src/main/resources/conf/ddl/postgres/migrations/V48__Add_stuck_detection_llu.sql b/cuebot/src/main/resources/conf/ddl/postgres/migrations/V48__Add_stuck_detection_llu.sql new file mode 100644 index 0000000000..acb4b65f89 --- /dev/null +++ b/cuebot/src/main/resources/conf/ddl/postgres/migrations/V48__Add_stuck_detection_llu.sql @@ -0,0 +1,6 @@ +-- Minutes without progress (log, CPU, or IO) before RQD kills a frame as stuck. +-- 0 = stuck detection disabled. + +ALTER TABLE show_service ADD COLUMN int_stuck_detection_llu INT DEFAULT 0 NOT NULL; +ALTER TABLE service ADD COLUMN int_stuck_detection_llu INT DEFAULT 0 NOT NULL; +ALTER TABLE layer ADD COLUMN int_stuck_detection_llu INT DEFAULT 0 NOT NULL; diff --git a/cuebot/src/test/java/com/imageworks/spcue/test/dao/postgres/ServiceDaoTests.java b/cuebot/src/test/java/com/imageworks/spcue/test/dao/postgres/ServiceDaoTests.java index db209f22b0..b49e0ea160 100644 --- a/cuebot/src/test/java/com/imageworks/spcue/test/dao/postgres/ServiceDaoTests.java +++ b/cuebot/src/test/java/com/imageworks/spcue/test/dao/postgres/ServiceDaoTests.java @@ -183,6 +183,7 @@ public void testUpdateServiceOverride() { s.minCores = 200; s.timeout = 10; s.timeout_llu = 10; + s.stuck_detection_llu = 20; s.minMemory = CueUtil.GB8; s.minGpuMemory = CueUtil.GB4; s.threadable = true; @@ -197,6 +198,8 @@ public void testUpdateServiceOverride() { assertEquals(s.minCores, s1.minCores); assertEquals(s.timeout, s1.timeout); assertEquals(s.timeout_llu, s1.timeout_llu); + assertEquals(s.stuck_detection_llu, s1.stuck_detection_llu); + assertEquals(20, s1.stuck_detection_llu); assertEquals(s.minMemory, s1.minMemory); assertEquals(s.minGpuMemory, s1.minGpuMemory); assertEquals(s.threadable, s1.threadable); diff --git a/cuebot/src/test/java/com/imageworks/spcue/test/dispatcher/FrameCompleteHandlerFrameStateTests.java b/cuebot/src/test/java/com/imageworks/spcue/test/dispatcher/FrameCompleteHandlerFrameStateTests.java index 7ab529c697..a63be89526 100644 --- a/cuebot/src/test/java/com/imageworks/spcue/test/dispatcher/FrameCompleteHandlerFrameStateTests.java +++ b/cuebot/src/test/java/com/imageworks/spcue/test/dispatcher/FrameCompleteHandlerFrameStateTests.java @@ -177,6 +177,24 @@ public void testLluTimeoutKillsFrame() { assertEquals(FrameState.DEAD, determine(report)); } + @Test + public void testStuckFrameWaitsForRetryDespiteStaleLlu() { + // A stuck kill (303) is usually host-local; it must retry even though the LLU is + // stale enough that the timeout_llu branch below would return DEAD. + layer.timeout_llu = 30; + long staleLluTime = System.currentTimeMillis() / 1000 - 3600; + FrameCompleteReport report = FrameCompleteReport + .newBuilder(report(Dispatcher.EXIT_STATUS_FRAME_STUCK, 0)) + .setFrame(RunningFrameInfo.newBuilder().setLluTime(staleLluTime).build()).build(); + assertEquals(FrameState.WAITING, determine(report)); + } + + @Test + public void testStuckFrameDiesWhenRetriesExhausted() { + frame.retries = job.maxRetries; + assertEquals(FrameState.DEAD, determine(report(Dispatcher.EXIT_STATUS_FRAME_STUCK, 0))); + } + @Test public void testLayerTimeoutKillsFrame() { layer.timeout = 10; diff --git a/cuebot/src/test/java/com/imageworks/spcue/test/service/ServiceManagerTests.java b/cuebot/src/test/java/com/imageworks/spcue/test/service/ServiceManagerTests.java index d9b67e7aa2..63b01ccc36 100644 --- a/cuebot/src/test/java/com/imageworks/spcue/test/service/ServiceManagerTests.java +++ b/cuebot/src/test/java/com/imageworks/spcue/test/service/ServiceManagerTests.java @@ -83,11 +83,13 @@ public void testCreateService() { s.threadable = false; s.timeout = 0; s.timeout_llu = 0; + s.stuck_detection_llu = 25; s.tags.addAll(Sets.newHashSet("general")); serviceManager.createService(s); ServiceEntity newService = serviceManager.getService(s.id); assertEquals(s, newService); + assertEquals(25, newService.stuck_detection_llu); } @Test @@ -99,6 +101,7 @@ public void testOverrideExistingService() { s.minCores = 400; s.timeout = 10; s.timeout_llu = 10; + s.stuck_detection_llu = 15; s.minMemory = CueUtil.GB8; s.minGpuMemory = CueUtil.GB2; s.threadable = false; @@ -112,6 +115,7 @@ public void testOverrideExistingService() { assertEquals(400, newService.minCores); assertEquals(10, newService.timeout); assertEquals(10, newService.timeout_llu); + assertEquals(15, newService.stuck_detection_llu); assertEquals(CueUtil.GB8, newService.minMemory); assertEquals(CueUtil.GB2, newService.minGpuMemory); assertFalse(newService.threadable); @@ -130,6 +134,12 @@ public void testOverrideExistingService() { @Rollback(true) public void testJobLaunch() { + // Give the primary service a stuck-detection window so the inheritance + // assertion below is not comparing default zeros. + ServiceEntity shellService = serviceManager.getService("shell"); + shellService.stuck_detection_llu = 42; + serviceManager.updateService(shellService); + JobSpec spec = jobLauncher.parse(new File("src/test/resources/conf/jobspec/services.xml")); jobLauncher.launch(spec); @@ -148,6 +158,8 @@ public void testJobLaunch() { assertEquals(shell.minGpuMemory, shellLayer.minimumGpuMemory); assertFalse(shellLayer.isThreadable); assertEquals(shell.tags, shellLayer.tags); + // Layers inherit stuck_detection_llu from their primary service + assertEquals(42, shellLayer.stuck_detection_llu); assertThat(shellLayer.services, contains("shell", "katana", "unknown")); assertEquals(prman.minCores, prmanLayer.minimumCores); diff --git a/cuegui/cuegui/LayerDialog.py b/cuegui/cuegui/LayerDialog.py index 3f54ae266f..c88a62ade5 100644 --- a/cuegui/cuegui/LayerDialog.py +++ b/cuegui/cuegui/LayerDialog.py @@ -170,6 +170,13 @@ def __init__(self, layers, parent=None): self.__timeout_llu.setSuffix(" minutes") self.__timeout_llu.setSpecialValueText("No timeout") + # Stuck detection LLU + self.__stuck_detection_llu = QtWidgets.QSpinBox(self) + self.__stuck_detection_llu.setRange(0, 4320) + self.__stuck_detection_llu.setSingleStep(1) + self.__stuck_detection_llu.setSuffix(" minutes") + self.__stuck_detection_llu.setSpecialValueText("Disabled") + # Memory Optimizer self.__mem_opt = QtWidgets.QCheckBox() self.__mem_opt.setChecked(self.getMemoryOptSetting()) @@ -228,6 +235,7 @@ def __init__(self, layers, parent=None): self.__max_gpus.setValue(self.getMaxGpus()) self.__timeout.setValue(self.getTimeout()) self.__timeout_llu.setValue(self.getTimeoutLLU()) + self.__stuck_detection_llu.setValue(self.getStuckDetectionLLU()) QtWidgets.QVBoxLayout(self) @@ -272,6 +280,10 @@ def __init__(self, layers, parent=None): self.__timeout_llu, False), multiSelect)) + layout.addWidget(EnableableItem(LayerPropertiesItem("Stuck Detection LLU:", + self.__stuck_detection_llu, + False), + multiSelect)) layout.addStretch() self.__group.setLayout(layout) @@ -336,6 +348,8 @@ def apply(self): layer.setTimeout(self.__timeout.value()) if self.__timeout_llu.isEnabled(): layer.setTimeoutLLU(self.__timeout_llu.value()) + if self.__stuck_detection_llu.isEnabled(): + layer.setStuckDetectionLLU(self.__stuck_detection_llu.value()) if self.__tags.isEnabled(): self.__tags.apply() if self.__limits.isEnabled(): @@ -412,6 +426,14 @@ def getTimeoutLLU(self): result = layer.data.timeout_llu return result + def getStuckDetectionLLU(self): + """Gets the layer stuck-detection threshold (minutes, 0 = disabled).""" + result = 0 + for layer in self.__layers: + if layer.data.stuck_detection_llu > result: + result = layer.data.stuck_detection_llu + return result + def getMemoryOptSetting(self): """Gets whether the layer has memory optimizer enabled.""" result = False diff --git a/cuegui/cuegui/ServiceDialog.py b/cuegui/cuegui/ServiceDialog.py index 48d7473bdb..8df61c4e7e 100644 --- a/cuegui/cuegui/ServiceDialog.py +++ b/cuegui/cuegui/ServiceDialog.py @@ -73,6 +73,10 @@ def __init__(self, parent=None): self.timeout_llu = QtWidgets.QSpinBox(self) self.timeout_llu.setRange(0, 4320) self.timeout_llu.setValue(0) + self.stuck_detection_llu = QtWidgets.QSpinBox(self) + self.stuck_detection_llu.setRange(0, 4320) + self.stuck_detection_llu.setValue(0) + self.stuck_detection_llu.setSpecialValueText("Disabled") self.min_memory_increase = QtWidgets.QSpinBox(self) self.min_memory_increase.setRange(0, int(self._cfg().get('max_memory', 48)) * 1024) self.min_memory_increase.setValue(0) @@ -93,17 +97,19 @@ def __init__(self, parent=None): layout.addWidget(self.timeout, 6, 1) layout.addWidget(QtWidgets.QLabel("Timeout LLU (in minutes):", self), 7, 0) layout.addWidget(self.timeout_llu, 7, 1) - layout.addWidget(QtWidgets.QLabel("OOM Increase MB:", self), 8, 0) - layout.addWidget(self.min_memory_increase, 8, 1) + layout.addWidget(QtWidgets.QLabel("Stuck detection LLU (in minutes):", self), 8, 0) + layout.addWidget(self.stuck_detection_llu, 8, 1) + layout.addWidget(QtWidgets.QLabel("OOM Increase MB:", self), 9, 0) + layout.addWidget(self.min_memory_increase, 9, 1) self._tags_w = cuegui.TagsWidget.TagsWidget(allowed_tags=cuegui.Constants.ALLOWED_TAGS) - layout.addWidget(self._tags_w, 9, 0, 1, 2) + layout.addWidget(self._tags_w, 10, 0, 1, 2) self.__buttons = QtWidgets.QDialogButtonBox(QtWidgets.QDialogButtonBox.Save, QtCore.Qt.Horizontal, self) self.__buttons.setDisabled(True) - layout.addWidget(self.__buttons, 10, 1) + layout.addWidget(self.__buttons, 11, 1) self.__buttons.accepted.connect(self.save) # pylint: disable=no-member @@ -139,6 +145,7 @@ def setService(self, service): self._tags_w.set_tags(service.data.tags) self.timeout.setValue(service.data.timeout) self.timeout_llu.setValue(service.data.timeout_llu) + self.stuck_detection_llu.setValue(service.data.stuck_detection_llu) self.min_memory_increase.setValue(service.data.min_memory_increase // 1024) def new(self): @@ -156,6 +163,7 @@ def new(self): self.min_gpu_memory.setValue(self.gpu_min_mb) self.timeout.setValue(0) self.timeout_llu.setValue(0) + self.stuck_detection_llu.setValue(0) self.min_memory_increase.setValue(2048) self._tags_w.set_tags(['general']) @@ -184,6 +192,13 @@ def save(self): "The minimum memory increase must be more than 0 MB") return + if 0 < self.timeout_llu.value() <= self.stuck_detection_llu.value(): + # Cuebot's blind LLU kill fires first and RQD's verified stuck kill never runs + QtWidgets.QMessageBox.warning( + self, "Warning", + "Timeout LLU should be larger than the stuck detection LLU, otherwise " + "frames time out on log staleness before RQD can verify they are stuck.") + service = opencue.wrappers.service.Service() if self.__service: service.data.id = self.__service.data.id @@ -195,6 +210,7 @@ def save(self): service.setMinGpuMemory(self.min_gpu_memory.value() * 1024) service.setTimeout(self.timeout.value()) service.setTimeoutLLU(self.timeout_llu.value()) + service.setStuckDetectionLLU(self.stuck_detection_llu.value()) service.setMinMemoryIncrease(self.min_memory_increase.value() * 1024) service.setTags(self._tags_w.get_tags()) diff --git a/proto/src/job.proto b/proto/src/job.proto index 581a339460..4a285693ab 100644 --- a/proto/src/job.proto +++ b/proto/src/job.proto @@ -400,6 +400,9 @@ service LayerInterface { // Set whether the LLU timeout for frames in the layer rpc SetTimeoutLLU(LayerSetTimeoutLLURequest) returns (LayerSetTimeoutLLUResponse); + // Set the stuck-detection threshold (minutes without progress) for frames in the layer + rpc SetStuckDetectionLLU(LayerSetStuckDetectionLLURequest) returns (LayerSetStuckDetectionLLUResponse); + // Staggers the specified frame range. rpc StaggerFrames(LayerStaggerFramesRequest) returns (LayerStaggerFramesResponse); } @@ -737,6 +740,9 @@ message Layer { int64 start_after = 26; // Free-text provenance for start_after, displayed verbatim. string start_after_reason = 27; + // Minutes without progress (log, CPU, or IO) before RQD kills a frame as stuck. + // 0 = stuck detection disabled. Sourced from the layer's service. + int32 stuck_detection_llu = 28; } message LayerSeq { @@ -1838,6 +1844,14 @@ message LayerSetTimeoutLLURequest { message LayerSetTimeoutLLUResponse {} // Empty +// SetStuckDetectionLLU +message LayerSetStuckDetectionLLURequest { + Layer layer = 1; + int32 stuck_detection_llu = 2; +} + +message LayerSetStuckDetectionLLUResponse {} // Empty + // StaggerFrames message LayerStaggerFramesRequest { diff --git a/proto/src/rqd.proto b/proto/src/rqd.proto index 621a13212c..67385ce077 100644 --- a/proto/src/rqd.proto +++ b/proto/src/rqd.proto @@ -126,6 +126,9 @@ message RunFrame { int64 hard_memory_limit = 27; int32 pid = 28; string loki_url = 29; + // Minutes without progress before RQD kills this frame as stuck. 0 = never inspect. + // Sourced from the layer's service. + int32 stuck_detection_llu = 30; } message RunFrameSeq { diff --git a/proto/src/service.proto b/proto/src/service.proto index 2c0a74774e..b6e2da2299 100644 --- a/proto/src/service.proto +++ b/proto/src/service.proto @@ -55,6 +55,9 @@ message Service { int32 min_gpus = 11; int32 max_gpus = 12; int32 min_memory_increase = 13; + // Minutes without progress (log, CPU, or IO) before RQD kills a frame as stuck. + // 0 = stuck detection disabled. + int32 stuck_detection_llu = 14; } message ServiceSeq { diff --git a/pycue/opencue/wrappers/layer.py b/pycue/opencue/wrappers/layer.py index 351aa2fe01..8f05a6eb5b 100644 --- a/pycue/opencue/wrappers/layer.py +++ b/pycue/opencue/wrappers/layer.py @@ -223,6 +223,16 @@ def setTimeoutLLU(self, timeout_llu): layer=self.data, timeout_llu=timeout_llu), timeout=Cuebot.Timeout) + def setStuckDetectionLLU(self, stuck_detection_llu): + """Set the stuck-detection threshold for frames in this layer. + :type stuck_detection_llu: int + :param stuck_detection_llu: minutes without progress before RQD kills a + frame as stuck; 0 disables stuck detection + """ + return self.stub.SetStuckDetectionLLU(job_pb2.LayerSetStuckDetectionLLURequest( + layer=self.data, stuck_detection_llu=stuck_detection_llu), + timeout=Cuebot.Timeout) + def setStartAfter(self, epoch_seconds, username=None): """Defers booking of this layer: no frame of the layer will start before the given time. diff --git a/pycue/opencue/wrappers/service.py b/pycue/opencue/wrappers/service.py index 9e0aaec137..d798f86def 100644 --- a/pycue/opencue/wrappers/service.py +++ b/pycue/opencue/wrappers/service.py @@ -258,6 +258,24 @@ def setTimeoutLLU(self, timeout_llu: int) -> None: """ self.data.timeout_llu = timeout_llu + def stuckDetectionLLU(self) -> int: + """Returns the default service stuck-detection threshold in minutes. + + :rtype: int + :return: Minutes without progress (log, CPU, or IO) before RQD kills a + frame as stuck. 0 means stuck detection is disabled. + """ + return self.data.stuck_detection_llu + + def setStuckDetectionLLU(self, stuck_detection_llu: int) -> None: + """Sets the default service stuck-detection threshold. + + :type stuck_detection_llu: int + :param stuck_detection_llu: Minutes without progress (log, CPU, or IO) + before RQD kills a frame as stuck. 0 disables stuck detection. + """ + self.data.stuck_detection_llu = stuck_detection_llu + def minMemoryIncrease(self): """Gets the default service minimum memory increment""" return self.data.min_memory_increase diff --git a/rust/config/rqd.yaml b/rust/config/rqd.yaml index 5c55e83672..a7efc9cdb3 100644 --- a/rust/config/rqd.yaml +++ b/rust/config/rqd.yaml @@ -166,6 +166,11 @@ runner: # Default: false # run_on_docker: false + # Host-level master switch for stuck-frame detection. A frame is only inspected when its + # service opted in on Cuebot (stuck_detection_llu > 0); with no opt-in this switch is inert. + # Signals are Linux-only. Default: true + # stuck_detection_enabled: true + # Default user ID for running jobs # Default: 1000 # default_uid: 1000 diff --git a/rust/crates/dummy-cuebot/src/rqd_client.rs b/rust/crates/dummy-cuebot/src/rqd_client.rs index ab3ce01b40..a2c471413e 100644 --- a/rust/crates/dummy-cuebot/src/rqd_client.rs +++ b/rust/crates/dummy-cuebot/src/rqd_client.rs @@ -70,6 +70,7 @@ impl DummyRqdClient { hard_memory_limit: 0, pid: 0, loki_url: "".to_string(), + stuck_detection_llu: 0, #[allow(deprecated)] job_temp_dir: "deprecated".to_string(), diff --git a/rust/crates/rqd/src/config/mod.rs b/rust/crates/rqd/src/config/mod.rs index 11550bfd33..a761854075 100644 --- a/rust/crates/rqd/src/config/mod.rs +++ b/rust/crates/rqd/src/config/mod.rs @@ -362,6 +362,10 @@ pub struct RunnerConfig { /// Number of trailing log lines scanned against `log_exit_status_rules` when a frame /// fails. Set to 0, or leave `log_exit_status_rules` empty, to disable log scanning. pub log_scan_last_lines: usize, + /// Host-level master switch for stuck-frame detection. Even when enabled, a frame is only + /// inspected if its RunFrame carries a non-zero stuck_detection_llu (opt-in per service on + /// Cuebot). Signals are Linux-only; on other platforms detection is inert. + pub stuck_detection_enabled: bool, /// Ordered list of regex→exit-status rules applied to failed frames' logs. The first /// matching rule wins. Empty by default, which disables the feature. pub log_exit_status_rules: Vec, @@ -429,6 +433,7 @@ impl Default for RunnerConfig { docker_default_image: "ubuntu:latest".to_string(), docker_images: HashMap::new(), log_scan_last_lines: 50, + stuck_detection_enabled: true, log_exit_status_rules: Vec::new(), log_exit_status_rules_reload_interval: Duration::from_secs(300), // 5 min compiled_exit_status_rules: Arc::new(RwLock::new(None)), diff --git a/rust/crates/rqd/src/frame/docker_running_frame.rs b/rust/crates/rqd/src/frame/docker_running_frame.rs index 5b6f9ae600..256e32c695 100644 --- a/rust/crates/rqd/src/frame/docker_running_frame.rs +++ b/rust/crates/rqd/src/frame/docker_running_frame.rs @@ -59,7 +59,9 @@ impl RunningFrame { } return; } - let logger = Arc::new(logger_base.unwrap()); + let logger_handle: FrameLogger = logger_base.unwrap(); + self.attach_logger(logger_handle.clone()); + let logger = Arc::new(logger_handle); let exit_code = if recover_mode { match self.recover_inner(Arc::clone(&logger)).await { diff --git a/rust/crates/rqd/src/frame/logging.rs b/rust/crates/rqd/src/frame/logging.rs index e6695027ec..c5a7a38c2b 100644 --- a/rust/crates/rqd/src/frame/logging.rs +++ b/rust/crates/rqd/src/frame/logging.rs @@ -21,8 +21,11 @@ use std::{ fs::{self, File, Permissions}, io::Write, path::Path, - sync::{Arc, Mutex}, - time::SystemTime, + sync::{ + atomic::{AtomicU64, Ordering}, + Arc, Mutex, + }, + time::{SystemTime, UNIX_EPOCH}, }; #[cfg(unix)] use std::os::unix::fs::PermissionsExt; @@ -37,6 +40,17 @@ pub trait FrameLoggerT { // Write a byte stream #[allow(dead_code)] fn write(&self, bytes: &[u8]); + /// Epoch seconds of the last write through this logger. Unlike the log file's mtime, + /// this is tracked in-process, so it works for Loki-backed frames and never touches a + /// possibly hung filesystem. Used by stuck-frame detection as the log-traction signal. + fn last_write_epoch(&self) -> u64; +} + +fn epoch_now() -> u64 { + SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default() + .as_secs() } pub struct FrameLoggerBuilder {} @@ -62,6 +76,7 @@ pub struct FrameFileLogger { _path: String, prepend_timestamp: bool, file_descriptor: Mutex, + last_write: AtomicU64, } impl FrameFileLogger { @@ -105,6 +120,7 @@ impl FrameFileLogger { _path: path, prepend_timestamp, file_descriptor, + last_write: AtomicU64::new(epoch_now()), }) } @@ -273,6 +289,7 @@ pub struct FrameLokiLogger { agent: Agent, loki_url: String, labels: HashMap, + last_write: AtomicU64, } impl FrameLokiLogger { @@ -288,6 +305,7 @@ impl FrameLokiLogger { agent, loki_url, labels, + last_write: AtomicU64::new(epoch_now()), }) } @@ -320,6 +338,7 @@ impl FrameLokiLogger { impl FrameLoggerT for FrameLokiLogger { fn writeln(&self, line: &str) { + self.last_write.store(epoch_now(), Ordering::Relaxed); let timestamp = Utc::now().timestamp_nanos_opt().unwrap_or(0).to_string(); let payload = LokiPayload { streams: vec![Stream { @@ -345,10 +364,15 @@ impl FrameLoggerT for FrameLokiLogger { } } } + + fn last_write_epoch(&self) -> u64 { + self.last_write.load(Ordering::Relaxed) + } } impl FrameLoggerT for FrameFileLogger { fn writeln(&self, text: &str) { + self.last_write.store(epoch_now(), Ordering::Relaxed); let mut line = String::with_capacity(text.len() + 8); if self.prepend_timestamp { let time_str: DateTime = SystemTime::now().into(); @@ -373,6 +397,7 @@ impl FrameLoggerT for FrameFileLogger { } fn write(&self, bytes: &[u8]) { + self.last_write.store(epoch_now(), Ordering::Relaxed); let mut buff: Vec = Vec::with_capacity(bytes.len()); if self.prepend_timestamp { @@ -400,12 +425,17 @@ impl FrameLoggerT for FrameFileLogger { } } } + + fn last_write_epoch(&self) -> u64 { + self.last_write.load(Ordering::Relaxed) + } } #[cfg(test)] /// A memory logger, meant for being used on test environments pub struct TestLogger { lines: Mutex>, + pub(crate) last_write: AtomicU64, } #[cfg(test)] @@ -413,6 +443,7 @@ impl TestLogger { pub fn init() -> Self { TestLogger { lines: Mutex::new(Vec::new()), + last_write: AtomicU64::new(epoch_now()), } } @@ -429,12 +460,14 @@ impl TestLogger { #[cfg(test)] impl FrameLoggerT for TestLogger { fn writeln(&self, line: &str) { + self.last_write.store(epoch_now(), Ordering::Relaxed); self.lines.lock().unwrap().push(line.to_string()); println!("{}", line); } fn write(&self, bytes: &[u8]) { + self.last_write.store(epoch_now(), Ordering::Relaxed); if let Ok(text) = std::str::from_utf8(bytes) { self.lines.lock().unwrap().push(text.to_string()); print!("{}", text); @@ -447,6 +480,10 @@ impl FrameLoggerT for TestLogger { println!("", bytes.len()); } } + + fn last_write_epoch(&self) -> u64 { + self.last_write.load(Ordering::Relaxed) + } } #[cfg(test)] @@ -455,6 +492,48 @@ mod tests { use std::io::Read; use tempfile::NamedTempFile; + #[test] + fn test_file_logger_last_write_epoch_advances_on_writeln() { + let temp_file = NamedTempFile::new().unwrap(); + let temp_path = temp_file.path().to_string_lossy().to_string(); + let logger = FrameFileLogger::init(temp_path, false, None).unwrap(); + + let epoch_at_init = logger.last_write_epoch(); + assert!(epoch_at_init > 0); + + // Force a visible epoch step so the bump is observable in whole seconds + logger.last_write.store(1, Ordering::Relaxed); + logger.writeln("some progress"); + assert!(logger.last_write_epoch() >= epoch_at_init); + + logger.last_write.store(1, Ordering::Relaxed); + logger.write(b"more progress\n"); + assert!(logger.last_write_epoch() >= epoch_at_init); + } + + #[test] + fn test_loki_logger_last_write_epoch_advances_on_writeln() { + use opencue_proto::rqd::RunFrame; + + // Connection-refused endpoint: the push fails, but the traction signal must still + // register the write attempt. + let run_frame = RunFrame { + job_name: "job".to_string(), + frame_name: "frame".to_string(), + user_name: "user".to_string(), + frame_id: "id".to_string(), + loki_url: "http://127.0.0.1:1".to_string(), + ..Default::default() + }; + let logger = FrameLokiLogger::init(run_frame).unwrap(); + let epoch_at_init = logger.last_write_epoch(); + assert!(epoch_at_init > 0); + + logger.last_write.store(1, Ordering::Relaxed); + logger.writeln("some progress"); + assert!(logger.last_write_epoch() >= epoch_at_init); + } + #[test] fn test_frame_file_logger_write_basic() { // Create a temporary file for testing diff --git a/rust/crates/rqd/src/frame/running_frame.rs b/rust/crates/rqd/src/frame/running_frame.rs index 8475269c06..3b87198347 100644 --- a/rust/crates/rqd/src/frame/running_frame.rs +++ b/rust/crates/rqd/src/frame/running_frame.rs @@ -18,7 +18,7 @@ use std::os::fd::IntoRawFd; use std::os::fd::{FromRawFd, RawFd}; #[cfg(unix)] use std::os::unix::process::ExitStatusExt; -use std::time::SystemTime; +use std::time::{SystemTime, UNIX_EPOCH}; use std::{ collections::HashMap, env, @@ -26,7 +26,7 @@ use std::{ path::Path, process::ExitStatus, sync::atomic::{AtomicBool, Ordering}, - sync::{Arc, RwLock}, + sync::{Arc, Mutex, RwLock}, }; use std::{process::Stdio, thread}; use tokio::time::{self, Duration}; @@ -39,10 +39,10 @@ use tokio::io::AsyncReadExt; use tokio::{io::AsyncBufReadExt, task::JoinHandle}; use tracing::{error, info, trace, warn}; -use crate::system::OOM_REASON_MSG; +use crate::system::{OOM_REASON_MSG, STUCK_EXIT_STATUS, STUCK_REASON_MSG}; use crate::{ frame::frame_cmd::FrameCmdBuilder, - system::manager::{HostMemSnapshot, PeerMem, ProcessStats}, + system::manager::{HostMemSnapshot, PeerMem, ProcessStats, SessionProgress}, }; use serde::{Deserialize, Serialize}; @@ -167,6 +167,33 @@ pub struct RunningFrame { #[serde(skip_serializing)] #[serde(skip_deserializing)] latest_host_mem_snapshot: RwLock>>, + /// Logger this frame writes through, attached by `run`/`run_docker` once created. Gives + /// stuck-frame detection its log-traction signal (in-process, so it works for Loki frames + /// and never stats a possibly hung filesystem) and a channel to write the kill footer. + /// Transient, never persisted in frame snapshots. + #[serde(skip_serializing)] + #[serde(skip_deserializing)] + attached_logger: RwLock>, + /// Stuck-frame detection state, updated once per monitor cycle. Transient: after an RQD + /// restart tracking restarts fresh, which fails open (recovered frames get a full + /// threshold window before they can be flagged). + #[serde(skip_serializing)] + #[serde(skip_deserializing)] + stuck_tracker: Mutex>, + /// Guards the kill footer to a single write per frame. A kill that fails unfreezes the + /// frame so the next monitor cycle retries, and without this the retry would append + /// another footer every cycle. Transient, never persisted in frame snapshots. + #[serde(skip_serializing)] + #[serde(skip_deserializing)] + stuck_footer_written: AtomicBool, +} + +/// Last observed progress sample and the moment any signal last moved. +/// See `RunningFrame::observe_progress`. +struct StuckTracker { + last_progress_at: SystemTime, + last_log_epoch: u64, + last_progress: SessionProgress, } #[derive(Serialize, Deserialize, Debug)] @@ -299,6 +326,9 @@ impl RunningFrame { dangling_state_registed_at: RwLock::new(None), stats_frozen: AtomicBool::new(false), latest_host_mem_snapshot: RwLock::new(None), + attached_logger: RwLock::new(None), + stuck_tracker: Mutex::new(None), + stuck_footer_written: AtomicBool::new(false), } } @@ -443,14 +473,19 @@ impl RunningFrame { match &mut *state { FrameState::Created(_) => Err(miette!("Invalid State. Frame {} hasn't started", self)), FrameState::Running(running_state) => { - // Replace exit_signal to memory signal if kill_reason matches the memory check message - let modified_exit_signal = match &running_state.kill_reason { + // Kills issued by RQD itself encode their cause in the reported status: + // OOM kills replace the exit signal with Cuebot's memory-failure signal, and + // stuck kills replace the exit code with the frame-stuck status. + let (exit_code, modified_exit_signal) = match &running_state.kill_reason { Some(reason) if reason.contains(OOM_REASON_MSG) => { // 33 is the error signal hardcoded on Cuebot for memory issues // (See Dispatcher.java:EXIT_STATUS_MEMORY_FAILURE) - Some(33) + (exit_code, Some(33)) + } + Some(reason) if reason.contains(STUCK_REASON_MSG) => { + (STUCK_EXIT_STATUS, exit_signal) } - _ => exit_signal, + _ => (exit_code, exit_signal), }; // Create a new FinishedState with the current running state values @@ -696,7 +731,9 @@ impl RunningFrame { }; return; } - let logger = Arc::new(logger_base.unwrap()); + let logger_handle: FrameLogger = logger_base.unwrap(); + self.attach_logger(logger_handle.clone()); + let logger = Arc::new(logger_handle); let output = if recover_mode { self.recover_inner(Arc::clone(&logger)).await @@ -1687,6 +1724,16 @@ Render Frame Completed self.stats_frozen.store(true, Ordering::SeqCst); } + /// Unfreezes the frame statistics, re-enabling updates. + /// + /// Called when a kill that froze stats first could not be issued: `observe_progress` + /// skips frozen frames, so without unfreezing a failed stuck-kill would never be + /// re-detected and retried, and stats reporting would stay dead while the process + /// lives on. + pub fn unfreeze_stats(&self) { + self.stats_frozen.store(false, Ordering::SeqCst); + } + /// Stores the latest host-wide memory snapshot, shared from the monitor loop. /// /// The same `Arc` is pushed into every running frame each monitor cycle so that a @@ -1700,6 +1747,158 @@ Render Frame Completed *lock = Some(snapshot); } + /// Attaches the logger this frame writes through, exposing its in-process last-write + /// timestamp to stuck-frame detection and letting the monitor append the kill footer. + pub fn attach_logger(&self, logger: FrameLogger) { + let mut lock = self + .attached_logger + .write() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + *lock = Some(logger); + } + + fn logger_last_write(&self) -> Option { + self.attached_logger + .read() + .unwrap_or_else(|poisoned| poisoned.into_inner()) + .as_ref() + .map(|logger| logger.last_write_epoch()) + } + + /// Feeds one monitor-cycle progress sample into stuck-frame detection and returns how + /// long this frame has gone without any sign of progress. + /// + /// Progress is any of: a log write since the last cycle, a change in the session's + /// cpu/io counters, or a change in the session's process composition. Every uncertain + /// case fails open: no session sample (`None`, e.g. non-Linux), an unavailable CPU + /// signal, a frozen frame, or the first observation all reset the clock instead of + /// accumulating towards a kill. + pub fn observe_progress(&self, sample: Option) -> Option { + if self.stats_frozen.load(Ordering::SeqCst) { + return None; + } + let mut lock = self + .stuck_tracker + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + let now = SystemTime::now(); + let log_epoch = self.logger_last_write().unwrap_or(0); + + // The CPU signal is required for a verdict: without it the rule would degrade to + // log-silence alone (e.g. on platforms where /proc is unavailable). + let sample = match sample { + Some(sample) if sample.cpu_time.is_some() => sample, + _ => { + *lock = None; + return None; + } + }; + + match lock.as_mut() { + Some(tracker) => { + let iomoved = match (tracker.last_progress.io_bytes, sample.io_bytes) { + (Some(last), Some(current)) => last != current, + // An IO signal that appears or disappears is a change, not silence + (last, current) => last.is_some() != current.is_some(), + }; + let moved = tracker.last_log_epoch != log_epoch + || tracker.last_progress.cpu_time != sample.cpu_time + || tracker.last_progress.composition != sample.composition + || iomoved; + if moved { + tracker.last_progress_at = now; + } + tracker.last_log_epoch = log_epoch; + tracker.last_progress = sample; + now.duration_since(tracker.last_progress_at).ok() + } + None => { + *lock = Some(StuckTracker { + last_progress_at: now, + last_log_epoch: log_epoch, + last_progress: sample, + }); + Some(std::time::Duration::ZERO) + } + } + } + + /// Appends the stuck-kill evidence footer to the frame log. This is the artist's only + /// explanation for the frame dying with the frame-stuck status, so it renders everything + /// RQD knows: how long nothing moved, when the log and counters last did, and what each + /// session process was blocked on. + /// + /// Writes at most once per frame: a failed kill is retried on every subsequent monitor + /// cycle, and the footer describes a verdict that does not change between attempts. + pub fn write_stuck_footer( + &self, + no_progress: std::time::Duration, + threshold: std::time::Duration, + evidence: &[String], + ) { + if self.stuck_footer_written.swap(true, Ordering::SeqCst) { + return; + } + let logger = { + let lock = self + .attached_logger + .read() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + lock.clone() + }; + let Some(logger) = logger else { + warn!("Frame {}: no logger attached, skipping stuck footer", self); + return; + }; + let (last_progress_at, last_log_epoch) = { + let lock = self + .stuck_tracker + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + match lock.as_ref() { + Some(tracker) => (Some(tracker.last_progress_at), tracker.last_log_epoch), + None => (None, 0), + } + }; + let fmt_time = |time: SystemTime| { + DateTime::::from(time) + .format("%Y-%m-%d %H:%M:%S") + .to_string() + }; + let mut footer = String::new(); + footer.push_str("\n=== RQD: frame killed as stuck ===\n"); + footer.push_str(&format!( + "No progress (log, CPU, or IO) for {}s (threshold {}s).\n", + no_progress.as_secs(), + threshold.as_secs() + )); + if last_log_epoch > 0 { + footer.push_str(&format!( + "Last log write: {}\n", + fmt_time(UNIX_EPOCH + std::time::Duration::from_secs(last_log_epoch)) + )); + } + if let Some(last_progress_at) = last_progress_at { + footer.push_str(&format!( + "Last counter move: {}\n", + fmt_time(last_progress_at) + )); + } + if evidence.is_empty() { + footer.push_str("No per-process evidence available.\n"); + } else { + footer.push_str(&format!("Session processes ({}):\n", evidence.len())); + for line in evidence { + footer.push_str(line); + footer.push('\n'); + } + } + footer.push_str( + "The frame will be reported with exit status 303 (frame stuck) and retried by Cuebot.", + ); + logger.writeln(&footer); + } + /// Builds this frame's contribution to the host memory snapshot from its current stats. /// /// Memory values are in bytes. `reserved` is `None` when the frame declares no soft @@ -1827,6 +2026,212 @@ mod tests { use super::{match_exit_status_rules, read_last_lines, RunningFrame, LOG_SCAN_MAX_BYTES}; + + mod stuck_detection { + use super::*; + use crate::frame::logging::FrameLogger; + use crate::frame::running_frame::FrameState; + use crate::system::manager::SessionProgress; + use crate::system::{STUCK_EXIT_STATUS, STUCK_REASON_MSG}; + use std::sync::atomic::Ordering; + use std::time::Duration; + + fn frame() -> RunningFrame { + create_running_frame("sleep 1", 1, 0, HashMap::new()) + } + + fn sample(cpu: u64, io: Option, composition: u64) -> Option { + Some(SessionProgress { + cpu_time: Some(cpu), + io_bytes: io, + composition, + }) + } + + #[test] + fn first_observation_starts_the_clock_at_zero() { + let frame = frame(); + let elapsed = frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + assert!(elapsed < Duration::from_secs(1)); + } + + #[test] + fn no_movement_accumulates() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + let elapsed = frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + assert!(elapsed >= Duration::from_millis(20)); + } + + #[test] + fn cpu_movement_resets_the_clock() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + let elapsed = frame.observe_progress(sample(11, Some(100), 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn io_movement_resets_the_clock() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + let elapsed = frame.observe_progress(sample(10, Some(101), 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn io_signal_appearing_or_disappearing_is_movement_not_silence() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + let elapsed = frame.observe_progress(sample(10, None, 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + std::thread::sleep(Duration::from_millis(20)); + let elapsed = frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn composition_change_resets_the_clock() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + // A (pid, starttime) set change (fork, exit, or pid reuse) is progress + let elapsed = frame.observe_progress(sample(10, Some(100), 2)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn log_write_resets_the_clock() { + let frame = frame(); + let logger = Arc::new(TestLogger::init()); + frame.attach_logger(logger.clone() as FrameLogger); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + // Writes are tracked at second granularity; move the recorded epoch instead of + // sleeping over a second boundary. + logger.last_write.store(u64::MAX, Ordering::Relaxed); + let elapsed = frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn absent_sample_fails_open() { + let frame = frame(); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + std::thread::sleep(Duration::from_millis(20)); + // Signals became unavailable: no verdict, and the tracker resets so the frame + // gets a fresh threshold window when they come back. + assert!(frame.observe_progress(None).is_none()); + let elapsed = frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + assert!(elapsed < Duration::from_millis(20)); + } + + #[test] + fn missing_cpu_signal_fails_open() { + let frame = frame(); + let no_cpu = Some(SessionProgress { + cpu_time: None, + io_bytes: Some(100), + composition: 1, + }); + assert!(frame.observe_progress(no_cpu).is_none()); + } + + #[test] + fn frozen_frame_is_not_observed() { + let frame = frame(); + frame.freeze_stats(); + assert!(frame.observe_progress(sample(10, Some(100), 1)).is_none()); + } + + #[test] + fn stuck_kill_reason_overrides_exit_status() { + let frame = create_running_frame("sleep 1", 1, 0, HashMap::new()); + let frame = RunningFrame::init_started_for_test( + frame.request.clone(), + 0, + frame.config.clone(), + None, + None, + "localhost".to_string(), + std::time::Duration::from_secs(60), + ); + frame.get_pid_to_kill(STUCK_REASON_MSG).unwrap(); + frame.finish(143, Some(15), None).unwrap(); + match frame.get_state_copy() { + FrameState::Finished(finished) => { + assert_eq!(finished.exit_code, STUCK_EXIT_STATUS); + assert_eq!(finished.exit_signal, Some(15)); + } + other => panic!("expected finished state, got {:?}", other), + } + } + + #[test] + fn non_stuck_kill_keeps_exit_status() { + let frame = create_running_frame("sleep 1", 1, 0, HashMap::new()); + let frame = RunningFrame::init_started_for_test( + frame.request.clone(), + 0, + frame.config.clone(), + None, + None, + "localhost".to_string(), + std::time::Duration::from_secs(60), + ); + frame.get_pid_to_kill("manual kill").unwrap(); + frame.finish(143, Some(15), None).unwrap(); + match frame.get_state_copy() { + FrameState::Finished(finished) => { + assert_eq!(finished.exit_code, 143); + } + other => panic!("expected finished state, got {:?}", other), + } + } + + #[test] + fn stuck_footer_reaches_the_frame_log() { + let frame = frame(); + let logger = Arc::new(TestLogger::init()); + frame.attach_logger(logger.clone() as FrameLogger); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + frame.write_stuck_footer( + Duration::from_secs(1800), + Duration::from_secs(1200), + &[" 4711 S nfs_hog wchan=rpc_wait_bit_killable syscall=-".to_string()], + ); + let footer = logger.pop().expect("footer should have been written"); + assert!(footer.contains("frame killed as stuck")); + assert!(footer.contains("rpc_wait_bit_killable")); + assert!(footer.contains("303")); + } + + #[test] + fn stuck_footer_is_written_only_once() { + let frame = frame(); + let logger = Arc::new(TestLogger::init()); + frame.attach_logger(logger.clone() as FrameLogger); + frame.observe_progress(sample(10, Some(100), 1)).unwrap(); + let write = || { + frame.write_stuck_footer( + Duration::from_secs(1800), + Duration::from_secs(1200), + &[" 4711 S nfs_hog wchan=rpc_wait_bit_killable syscall=-".to_string()], + ) + }; + write(); + logger.pop().expect("footer should have been written"); + // A failed kill unfreezes the frame and the next monitor cycle retries; the + // footer must not be appended again. + write(); + assert!(logger.pop().is_none(), "footer was written more than once"); + } + } + fn create_running_frame( command: &str, num_cores: u32, @@ -1880,6 +2285,7 @@ mod tests { hard_memory_limit: 0, pid: 0, loki_url: loki_url.to_string(), + stuck_detection_llu: 0, #[allow(deprecated)] job_temp_dir: "".to_string(), diff --git a/rust/crates/rqd/src/system/linux.rs b/rust/crates/rqd/src/system/linux.rs index fa2c828ab3..6956e4293b 100644 --- a/rust/crates/rqd/src/system/linux.rs +++ b/rust/crates/rqd/src/system/linux.rs @@ -38,7 +38,7 @@ use uuid::Uuid; use crate::{config::MachineConfig, system::reservation::ProcessorStructure}; -use super::manager::{MachineGpuStats, MachineStat, ProcessStats, SystemManager}; +use super::manager::{MachineGpuStats, MachineStat, ProcessStats, SessionProgress, SystemManager}; pub struct LinuxSystem { config: MachineConfig, @@ -63,6 +63,11 @@ struct ProcessData { name: String, start_time: u64, run_time: u64, + /// utime+stime in clock ticks (fields 14 and 15 of /proc//stat). None if unparsable. + cpu_time: Option, + /// read_bytes+write_bytes from /proc//io. None when unreadable (requires + /// PTRACE_MODE_READ over the target). + io_bytes: Option, } impl ProcessData { @@ -536,9 +541,7 @@ impl LinuxSystem { fn read_temp_storage(&self) -> Result<(u64, u64)> { let stat = nix::sys::statvfs::statvfs(self.config.temp_path.as_str()) .into_diagnostic() - .wrap_err_with(|| { - format!("statvfs failed for temp path {}", self.config.temp_path) - })?; + .wrap_err_with(|| format!("statvfs failed for temp path {}", self.config.temp_path))?; let total_space = stat.blocks() as u64 * stat.fragment_size() as u64; let available_space = stat.blocks_available() as u64 * stat.fragment_size() as u64; Ok((total_space, available_space)) @@ -737,6 +740,16 @@ impl LinuxSystem { let (start_time, run_time) = self.calculate_process_time(start_time); + // utime (14) + stime (15): cpu progress counter for stuck-frame detection + let cpu_time = match ( + fields_stat[13].parse::(), + fields_stat[14].parse::(), + ) { + (Ok(utime), Ok(stime)) => Some(utime + stime), + _ => None, + }; + let io_bytes = Self::read_io_bytes(pid); + // Remove () let name = if name.len() > 2 { name[1..name.len() - 1].to_string() @@ -755,6 +768,8 @@ impl LinuxSystem { name, start_time, run_time, + cpu_time, + io_bytes, }) } else { Err(miette!("Invalid /proc/stat file for {pid}")) @@ -788,6 +803,27 @@ impl LinuxSystem { (start_time, run_time) } + /// Sum of read_bytes+write_bytes from /proc//io, or None when unreadable. + fn read_io_bytes(pid: u32) -> Option { + let content = std::fs::read_to_string(format!("/proc/{}/io", pid)).ok()?; + let mut total: Option = None; + for line in content.lines() { + if let Some(("read_bytes" | "write_bytes", value)) = line.split_once(':') { + let bytes = value.trim().parse::().ok()?; + total = Some(total.unwrap_or(0) + bytes); + } + } + total + } + + /// Best-effort single-value read of a /proc file, for the stuck-kill evidence footer. + fn read_proc_line(pid: u32, file: &str) -> Option { + std::fs::read_to_string(format!("/proc/{}/{}", pid, file)) + .ok() + .map(|content| content.trim().to_string()) + .filter(|content| !content.is_empty()) + } + fn calculate_proc_session_data(&self, session_id: &u32) -> Option { let mut children = Vec::new(); self.monitored_sessions.insert(*session_id); @@ -989,6 +1025,61 @@ impl SystemManager for LinuxSystem { })) } + fn collect_session_progress(&self, session_pid: u32) -> Option { + use std::collections::hash_map::DefaultHasher; + use std::hash::{Hash, Hasher}; + + let pids = self.session_processes.get(&session_pid)?; + let mut composition: Vec<(u32, u64)> = Vec::new(); + let mut cpu_time: Option = None; + let mut io_bytes: Option = None; + for pid in pids.iter() { + if let Some(proc) = self.cached_processes.get(pid) { + if proc.is_dead() { + continue; + } + composition.push((*pid, proc.start_time)); + if let Some(cpu) = proc.cpu_time { + cpu_time = Some(cpu_time.unwrap_or(0) + cpu); + } + if let Some(io) = proc.io_bytes { + io_bytes = Some(io_bytes.unwrap_or(0) + io); + } + } + } + if composition.is_empty() { + return None; + } + composition.sort_unstable(); + let mut hasher = DefaultHasher::new(); + composition.hash(&mut hasher); + Some(SessionProgress { + cpu_time, + io_bytes, + composition: hasher.finish(), + }) + } + + fn collect_session_evidence(&self, session_pid: u32) -> Vec { + let pids: Vec = match self.session_processes.get(&session_pid) { + Some(pids) => pids.clone(), + None => return Vec::new(), + }; + pids.into_iter() + .map(|pid| { + let (state, name) = self + .cached_processes + .get(&pid) + .map(|proc| (proc.state.clone(), proc.name.clone())) + .unwrap_or_else(|| ("?".to_string(), "?".to_string())); + let wchan = Self::read_proc_line(pid, "wchan").unwrap_or_else(|| "-".to_string()); + let syscall = + Self::read_proc_line(pid, "syscall").unwrap_or_else(|| "-".to_string()); + format!(" {pid} {state} {name} wchan={wchan} syscall={syscall}") + }) + .collect() + } + fn refresh_procs(&self) { if let Err(err) = self.refresh_procs_cache() { debug!("Failed to refresh procs on this system. {err}"); diff --git a/rust/crates/rqd/src/system/machine.rs b/rust/crates/rqd/src/system/machine.rs index ef88cc9885..a53e50a6e9 100644 --- a/rust/crates/rqd/src/system/machine.rs +++ b/rust/crates/rqd/src/system/machine.rs @@ -18,6 +18,7 @@ use crate::{ frame::manager, report::report_client, system::oom::{self, OOM_REASON_MSG}, + system::STUCK_REASON_MSG, }; use async_trait::async_trait; use bytesize::KIB; @@ -80,7 +81,7 @@ use crate::system::nimby::Nimby; pub struct MachineMonitor { maching_config: MachineConfig, report_client: Arc, - pub system_manager: Mutex, + pub system_manager: Arc>, pub core_manager: Arc>, pub running_frames_cache: Arc, /// Frames that have finished locally but whose completion has not yet been acknowledged by @@ -221,7 +222,7 @@ impl MachineMonitor { Ok(Self { maching_config: CONFIG.machine.clone(), report_client, - system_manager: Mutex::new(system_manager), + system_manager: Arc::new(Mutex::new(system_manager)), running_frames_cache: RunningFrameCache::init(), pending_completions: Arc::new(DashMap::new()), completion_notify: Arc::new(Notify::new()), @@ -445,6 +446,8 @@ impl MachineMonitor { let mut finished_frames: Vec> = Vec::new(); let mut running_frames: Vec<(Arc, RunningState)> = Vec::new(); let mut memory_aggressors: Vec<(Arc, u64)> = Vec::new(); + // (frame, session pid, time without progress, threshold) + let mut stuck_frames: Vec<(Arc, u32, Duration, Duration)> = Vec::new(); // Only keep running frames on the cache and store a copy of their state // to avoid having to deal with the state lock @@ -488,6 +491,32 @@ impl MachineMonitor { // Update stats for running frames running_frame.update_frame_stats(proc_stats); + + // Stuck-frame detection: opt-in per frame via RunFrame.stuck_detection_llu + // (minutes; 0 = never inspect). Signals are session-level counters that only + // the Linux system manager provides; observe_progress fails open whenever a + // signal is unavailable. + let stuck_detection_llu = running_frame.request.stuck_detection_llu; + if CONFIG.runner.stuck_detection_enabled + && !CONFIG.runner.run_on_docker + && stuck_detection_llu > 0 + { + let progress = { + let system_monitor = self.system_manager.lock().await; + system_monitor.collect_session_progress(running_state.pid) + }; + if let Some(no_progress) = running_frame.observe_progress(progress) { + let threshold = Duration::from_secs(stuck_detection_llu as u64 * 60); + if no_progress > threshold { + stuck_frames.push(( + Arc::clone(running_frame), + running_state.pid, + no_progress, + threshold, + )); + } + } + } } else if running_frame.is_dangling_expired() { // Frama proc was not found to be running even after a grace period warn!( @@ -581,6 +610,54 @@ impl MachineMonitor { _ => (), } + // Kill frames flagged as stuck. Mirrors the OOM path: freeze stats first so the + // reported usage isn't corrupted by reading dying processes, write the evidence + // footer while the session is still inspectable, then route through the frame + // manager so the kill gets the standard confirm/escalate treatment. + // + // Each kill runs on a detached task: the footer lands on the frame log, which may + // live on the very filesystem hang that got the frame stuck, and blocking the + // monitor loop on it would stop host reports for the whole host (Cuebot would mark + // it DOWN and kill every frame on it). Freezing stats inline also keeps the next + // monitor cycle from re-flagging the frame while its kill task is in flight. + for (frame, session_pid, no_progress, threshold) in stuck_frames { + frame.freeze_stats(); + let system_manager = Arc::clone(&self.system_manager); + tokio::spawn(async move { + let evidence = { + let system_monitor = system_manager.lock().await; + system_monitor.collect_session_evidence(session_pid) + }; + // The footer write is synchronous file IO that can wedge on the same hung + // mount; hand it to the blocking pool so the kill is never gated on it. + let footer_frame = Arc::clone(&frame); + tokio::task::spawn_blocking(move || { + footer_frame.write_stuck_footer(no_progress, threshold, &evidence); + }); + let kill_result = match manager::instance().await { + Ok(manager) => { + warn!( + "Killing stuck frame {}: no progress for {}s (threshold {}s)", + frame, + no_progress.as_secs(), + threshold.as_secs() + ); + manager + .kill_running_frame(&frame.frame_id, STUCK_REASON_MSG.to_string()) + .await + } + Err(err) => Err(err), + }; + if let Err(err) = kill_result { + warn!("Failed to kill stuck frame {}. {}", frame, err); + // Unfreeze so the next monitor cycle re-detects the frame and retries + // the kill. observe_progress skips frozen frames, so leaving stats + // frozen here would orphan the process forever with dead reporting. + frame.unfreeze_stats(); + } + }); + } + // Sanitize dangling reservations // This mechanism is redundant as enqueue_and_release_finished_frames_cores releases // resources reserved to finished frames. But leaking core reservations would lead to diff --git a/rust/crates/rqd/src/system/manager.rs b/rust/crates/rqd/src/system/manager.rs index 826a2ab083..cc7f4244a1 100644 --- a/rust/crates/rqd/src/system/manager.rs +++ b/rust/crates/rqd/src/system/manager.rs @@ -46,6 +46,21 @@ pub trait SystemManager { /// Collects stats of a process fn collect_proc_stats(&self, pid: u32, log_path: String) -> Result>; + /// Collects progress counters for a frame's process session, used by stuck-frame + /// detection. Returns None when the signals are unavailable (non-Linux platforms, or the + /// session is unknown), in which case the frame must never be flagged as stuck. + fn collect_session_progress(&self, session_pid: u32) -> Option { + let _ = session_pid; + None + } + + /// Collects per-process blocking evidence (state, wchan, current syscall) for the + /// stuck-kill log footer. Best effort; empty when unavailable. + fn collect_session_evidence(&self, session_pid: u32) -> Vec { + let _ = session_pid; + Vec::new() + } + /// Update info about procs currently active fn refresh_procs(&self); @@ -118,6 +133,25 @@ pub struct MachineGpuStats { pub _used_memory_by_unit: HashMap, } +/// Progress counters aggregated over a frame's process session, compared between monitor +/// cycles by stuck-frame detection. Any change in any field counts as progress. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct SessionProgress { + /// Sum of utime+stime (clock ticks) over the live processes in the session that + /// reported the counter. None only when no process reported one, which disables the + /// verdict entirely (the CPU signal is required for a frame to ever be flagged). + /// A process whose /proc entry cannot be read at all is absent from the session + /// altogether, so it also changes `composition` and therefore reads as progress. + pub cpu_time: Option, + /// Sum of read_bytes+write_bytes from /proc//io over the processes that reported + /// it. None only when no process did (the file needs PTRACE_MODE_READ); an absent IO + /// signal is simply not compared, never counted as zero. + pub io_bytes: Option, + /// Hash of the session's (pid, starttime) set. A fork or an exit changes it, and + /// starttime guards against pid reuse looking like continuity. + pub composition: u64, +} + /// Tracks memory and runtime statistics for a rendering process and its children. #[derive(Clone, Serialize, Deserialize)] pub struct ProcessStats { diff --git a/rust/crates/rqd/src/system/mod.rs b/rust/crates/rqd/src/system/mod.rs index ec98ea547e..cf065d6455 100644 --- a/rust/crates/rqd/src/system/mod.rs +++ b/rust/crates/rqd/src/system/mod.rs @@ -33,3 +33,12 @@ pub type PhysId = u32; pub type ThreadId = u32; pub use oom::OOM_REASON_MSG; + +/// Kill reason recorded when stuck-frame detection kills a frame. `RunningFrame::finish` +/// matches on this to override the reported exit status with `STUCK_EXIT_STATUS`. +pub static STUCK_REASON_MSG: &str = + "Frame killed by stuck-frame detection: no log, CPU, or IO progress"; + +/// Mirrors Cuebot's Dispatcher.EXIT_STATUS_FRAME_STUCK. Cuebot returns the frame to WAITING +/// (counting the retry) when it sees this status. +pub static STUCK_EXIT_STATUS: i32 = 303; diff --git a/rust/crates/rqd/src/system/oom.rs b/rust/crates/rqd/src/system/oom.rs index 2ca82f69ed..5b57861896 100644 --- a/rust/crates/rqd/src/system/oom.rs +++ b/rust/crates/rqd/src/system/oom.rs @@ -231,6 +231,7 @@ mod tests { hard_memory_limit: 0, pid: 0, loki_url: "".to_string(), + stuck_detection_llu: 0, #[allow(deprecated)] job_temp_dir: "".to_string(), #[allow(deprecated)] diff --git a/rust/crates/scheduler/src/pipeline/dispatcher/actor.rs b/rust/crates/scheduler/src/pipeline/dispatcher/actor.rs index d3b792cc52..3c7a5e8900 100644 --- a/rust/crates/scheduler/src/pipeline/dispatcher/actor.rs +++ b/rust/crates/scheduler/src/pipeline/dispatcher/actor.rs @@ -1319,6 +1319,9 @@ impl RqdDispatcherService { attributes: HashMap::new(), children: None, pid: 0, // Will be set by RQD + // Stuck detection is not plumbed through the scheduler's dispatch path yet, so + // scheduler-dispatched frames are never stuck-inspected by RQD. + stuck_detection_llu: 0, // Deprecated fields #[allow(deprecated)]