Gradle-output met parallelle code verwarrend

[ACM]

Voor de java-backend van Tweakers hebben we vanaf het begin meerdere servers.
Daar deployden we in eerste instantie met ANT en later met een mix van een klein ANT-"scriptje" en de rest in Gradle.

Dat ANT-script had daarin nog als enige taak om met een for-loop over de relevante hosts te gaan en daar naar een aantal van tegelijk te deployen (for-tag met parallel=true en threadcount=3), zodanig dat er geen moment is dat alle hosts down zijn door de deploy maar we ook weer niet onnodig hoeven te wachten tot iedere host klaar is (ca 6min per stuk).

Aan die functionaliteit wilde ik wat verbeteren en ik vond het daarbij ook tijd worden om helemaal af te stappen van die losse build.xml

Dat deel is gelukt, de parallel uitgevoerde loop is omgezet naar Groovy-code in de Gradle-scripts en de build.xml kan nu weg.
Wat me daarbij echter stoort is dat de output van diverse println's niet op de verwachte manier komt; overigens ging dat blijkbaar ook al mis met de ant-based versie, maar viel het toen minder op.

ik snap dat meldingen voor diverse hosts door elkaar kunnen komen, maar ook output die in het Gradle-script voor het starten van de parallelle-code komt pas na dat de output vanuit die loops is getoond.

16-02-2020 12:28:05.075 Host: hostA
16-02-2020 12:28:05.075 Host: hostB
16-02-2020 12:28:06.076 Host done: hostB
16-02-2020 12:28:06.076 Host done: hostA

> Task :testParallel
16-02-2020 12:28:05.071 starting test
16-02-2020 12:28:06.077 test complete

Mijn verwachting was dat die Host-regels tussen de 'starting test' en 'test complete' in zouden komen, ook de tijdstippen die ervoor staan suggereren dat dat zo zou horen... En uiteraard hoeft start/einde van hostA vs B niet per se in deze volgorde te staan.
Met een langere wachttijd komen overigens de 'done'-meldingen wel tussen "starting test" en "test complete" in, maar de start-meldingen komen alsnog ervoor.

Dit is een mini-versie van het originele Gradle-script dat het probleem reproduceert:

Groovy: build.gradle

import groovyx.gpars.GParsPool
import java.time.format.DateTimeFormatter

buildscript {
    repositories {
        mavenCentral()
    }
    dependencies {
        classpath "org.codehaus.gpars:gpars:1.2.1"
    }
}

task ('testParallel') {
    doLast {
        def hosts = ['hostA', 'hostB']
        def dateFormat = DateTimeFormatter.ofPattern("dd-MM-yyyy HH:mm:ss.SSS")

        println LocalDateTime.now().format(dateFormat) + " starting test"

        GParsPool.withPool() {
            hosts.eachParallel {
                String host ->
                    println LocalDateTime.now().format(dateFormat) + " Host: " + host
                    sleep 1000
                    println LocalDateTime.now().format(dateFormat) + " Host done: " + host
            }
        }

        println LocalDateTime.now().format(dateFormat) + " test complete"
    }
}

Mijn Groovy-kennis is beperkt tot het gebruik binnen Gradle en het is niet bepaald een standaard task binnen Gradle, dus ik kan uiteraard iets heel triviaals over het hoofd zien...

Wat kan ik doen om de voortgang in een logischere groepering te krijgen? Het hoeft uiteraard niet per se via println, dat is simpelweg wat ik nu gebruik.

[ Voor 3% gewijzigd door ACM op 16-02-2020 12:42 ]

[Postman]

Mijn eerste ingeving is iets met een flush want het komt over op mij alsof die println functie een bufferwriter is. Zou kunnen proberen om een system.out.flush() te doen om te zien of dat wel de juiste positie iets print.
Verder heb ik totaal geen kaas gegeten van Gradle build scripts dus wellicht dat het complete onzin is wat ik zeg. Je zou trouwens ook verwachten dat println zelf al een flush doet, maar misschien is dat dus alleen voorbehouden aan printf.

Edit: het is een simpele versie van je script, dus grote kans dat je wel een doFirst hebt en niet alleen de doLast gebruikt.

[ Voor 12% gewijzigd door Postman op 16-02-2020 20:26 ]

[ACM]

Postman schreef op zondag 16 februari 2020 @ 20:24:
Mijn eerste ingeving is iets met een flush want het komt over op mij alsof die println functie een bufferwriter is.

Er lijkt inderdaad iets gebuffered te worden, maar dat lijkt ook deels door Gradle zelf gedaan te worden omdat ie ook een voortgangsteller erbij afdrukt... wat zou suggereren dat de output in de main-thread opgevangen wordt door 'iets' en de andere threads niet. Maar wat daar precies voor zorgt?

Je zou trouwens ook verwachten dat println zelf al een flush doet, maar misschien is dat dus alleen voorbehouden aan printf.

Nou... aangezien de andere println's direct voorbij komen lijkt dat wel te flushen

Edit: het is een simpele versie van je script, dus grote kans dat je wel een doFirst hebt en niet alleen de doLast gebruikt.

Nee, deze specifieke task is bijna hetzelfde als de werkelijkheid. Het versimpelen zit 'm meer in dat ik alle overige tasks heb weggelaten, van deze task is het grootste verschil is dat de loop een niveau minder diep nest en geen echte deploy doet

Met doFirst, doLast of geen van beide en een directe closure in de task blijft het output zich hetzelfde gedragen.

[edit]
Je opmerking bracht me nog wel op een idee.

Je kan in Gradle naast println ook specifiek de "logger" gebruiken. En dan komt de output wel in de verwachte volgorde, waarschijnlijk omdat dan steeds dezelfde route voor de outputmessage wordt genomen ipv via een net wat andere voor de Threads.

[ Voor 12% gewijzigd door ACM op 16-02-2020 21:51 ]

[Postman]

ACM schreef op zondag 16 februari 2020 @ 21:23:
[edit]
Je opmerking bracht me nog wel op een idee.

Je kan in Gradle naast println ook specifiek de "logger" gebruiken. En dan komt de output wel in de verwachte volgorde, waarschijnlijk omdat dan steeds dezelfde route voor de outputmessage wordt genomen ipv via een net wat andere voor de Threads.

Fijn dat het in ieder geval opgelost is nu.

Ik ben zelf al een keer eerder tegen een probleem aangelopen met Threads en niet synchrone output. Kan me niet herinneren dat ik toen een oplossing gevonden heb, maar er staat me wel iets van bij dat dit ook nog eens per OS verschillend afgehandeld wordt (of tenminste iets met Tomcat en OS te maken had in mijn geval).

[ACM]

Postman schreef op maandag 17 februari 2020 @ 13:50:
Ik ben zelf al een keer eerder tegen een probleem aangelopen met Threads en niet synchrone output. Kan me niet herinneren dat ik toen een oplossing gevonden heb, maar er staat me wel iets van bij dat dit ook nog eens per OS verschillend afgehandeld wordt (of tenminste iets met Tomcat en OS te maken had in mijn geval).

Dat geloof ik wel. Gradle vervangt iig de standaard logger met iets dat ze zelf doen. Sterker nog, toen ik mijn oplossing in een losse Groovy-method stopte om wat duplicatie weg te werken, toen werkte het ineens weer niet... Blijkbaar is die global logger-property ook weer niet helemaal global

Dus nu moet ik de logger-property ook doorgeven aan die methode