XTend Performance example

As requested in the JSR223 performance thread I’ll post my code as an example to see if there is some room for improvements. I found that jython is ~160 times faster than xTend in a simple example.
The code here is for analyzing and to find out if there are possibilities in xTend to make it run faster.

What does it do:
I have six led strips in my room. Two in front of me, two to the left and two to the right. On is always facing up and one is facing down. I use this setup to illuminate the room when there is movement but also to signal various events:

  • washing mashine is done
  • I forgot to close the window and is getting cold
  • today is trash day and I have to remember to take it out
  • etc.

So there are various fades which can overlay each other and run at the same time. To make it more complicated, some fades run only on some led strips. Washing machine runs only on the lower strips, window only on the front lower but movement only on the upper strips.
To achieve this comfortably I wrote a fade scheduler. Unfortunately the code is very slow on the pi2. My goal was to get a refresh rate of 50ms so I can have really smooth fades. At the moment I have between 150ms and 750ms per fade step - so this is way to slow.
I am posting my code for analysis. Be aware that the code is very complex and is best viewed in the designer. If you want to run the code and you don’t have the dmx-binding just delete the dmx part. It should run fine without.

items

Group gWohnzimmerFADEs                            "Fades"

//-----------------------------------------------------------------------------------------------------------------------------------------------------------
// DMX Auswahl
//-----------------------------------------------------------------------------------------------------------------------------------------------------------
Number    Wohnzimmer_Fade_Zeit        "Fade Zeit ms [%d]"

Group    g_Licht_Wohnzimmer            (gWohnzimmerFADEs)
Group    g_Licht_Wohnzimmer_Oben        (g_Licht_Wohnzimmer)
Color   Wohnzimmer_Vorne_Oben        "Wohn V O"    (g_Licht_Wohnzimmer_Oben)        {dmx="CHANNEL[81/3], ON[FADE|5000:255,255,200:0], OFF[FADE|2000:0,0,0:0]"}
Color   Wohnzimmer_Rechts_Oben        "Wohn R O"    (g_Licht_Wohnzimmer_Oben)        {dmx="CHANNEL[73/3], ON[FADE|5000:255,255,200:0], OFF[FADE|2000:0,0,0:0]"}
Color   Wohnzimmer_Hinten_Oben        "Wohn H O"    (g_Licht_Wohnzimmer_Oben)        {dmx="CHANNEL[65/3], ON[FADE|5000:255,255,200:0], OFF[FADE|2000:0,0,0:0]"}

Group    g_Licht_Wohnzimmer_Unten    (g_Licht_Wohnzimmer)
Color    Wohnzimmer_Vorne_Unten        "Wohn V U"    (g_Licht_Wohnzimmer_Unten)        { dmx="CHANNEL[85/3],ON[FADE|5000:255,255,200:0],OFF[FADE|2000:0,0,0:0]" }
Color    Wohnzimmer_Rechts_Unten        "Wohn V U"    (g_Licht_Wohnzimmer_Unten)        { dmx="CHANNEL[77/3],ON[FADE|5000:255,255,200:0],OFF[FADE|2000:0,0,0:0]" }
Color    Wohnzimmer_Hinten_Unten        "Wohn V U"    (g_Licht_Wohnzimmer_Unten)        { dmx="CHANNEL[69/3],ON[FADE|5000:255,255,200:0],OFF[FADE|2000:0,0,0:0]" }

Group    g_Wohnzimmer_Fade_History
Color   Wohnzimmer_Vorne_Oben_0                    (g_Wohnzimmer_Fade_History)
Color   Wohnzimmer_Rechts_Oben_0                (g_Wohnzimmer_Fade_History)
Color   Wohnzimmer_Hinten_Oben_0                (g_Wohnzimmer_Fade_History)
Color    Wohnzimmer_Vorne_Unten_0                (g_Wohnzimmer_Fade_History)
Color    Wohnzimmer_Rechts_Unten_0                (g_Wohnzimmer_Fade_History)
Color    Wohnzimmer_Hinten_Unten_0                (g_Wohnzimmer_Fade_History)


//-----------------------------------------------------------------------------------------------------------------------------------------------------------
// DMX-Fades
//-----------------------------------------------------------------------------------------------------------------------------------------------------------
Switch    Wohnzimmer_Fade_Bewegung_Tag                "Bewegungsmelder Tag"            (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Bewegung_Nacht                "Bewegungsmelder Nacht"            (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Waschmaschine                "Waschmaschine fertig"            (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Schalter                    "Funkschalter"                    (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Muell                        "Muell raus bringen"            (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Schlafzimmerfenster            "Schlafzimmerfenster offen"        (gWohnzimmerFADEs)
Switch    Wohnzimmer_Fade_Alle_Aus                    "Alle aus"                        (gWohnzimmerFADEs)
Switch    Wohnzimmer_FADE_Luigi_online                "Luigi online"                    (gWohnzimmerFADEs)
Switch    Wohnzimmer_FADE_Luigi_offline                "Luigi offline"                    (gWohnzimmerFADEs)

code:

// Imports
import org.joda.time.*
import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*


import java.util.LinkedHashMap
import java.util.HashMap
import java.util.Map

import java.util.concurrent.locks.Lock
import java.util.concurrent.locks.ReentrantLock

var Lock    to_copy_lock    = new ReentrantLock()
var boolean to_copy_state    = false

var Lock    fades_lock    = new ReentrantLock()
var int        fades_anz    = 0

var HashMap<String, Object> fade_soll_map =
    newLinkedHashMap(
        "Vorne_Oben"    -> null as HSBType,
        "Rechts_Oben"    -> null as HSBType,
        "Hinten_Oben"    -> null as HSBType,
        "Vorne_Unten"    -> null as HSBType,
        "Rechts_Unten"    -> null as HSBType,
        "Hinten_Unten"    -> null as HSBType,
        "Wait"            -> false as Boolean,
        
        ""                -> null as Object
    ) as LinkedHashMap<String, Object>













rule "Fade Bewegungsmelder Tag an"
when
    Item Wohnzimmer_Fade_Bewegung_Tag received update ON
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)


    fade_soll_map.put( "Vorne_Oben",    new HSBType( "0,0,100"))
    fade_soll_map.put( "Rechts_Oben",    new HSBType( "0,0,100"))
    fade_soll_map.put( "Hinten_Oben",    new HSBType( "0,0,100"))

    Wohnzimmer_Fade_Zeit.sendCommand(3000)
end

rule "Fade Bewegungsmelder Nacht an"
when
    Item Wohnzimmer_Fade_Bewegung_Nacht received update ON
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)


    fade_soll_map.put( "Vorne_Oben",    new HSBType( "30,100,3"))
    fade_soll_map.put( "Rechts_Oben",    new HSBType( "30,100,3"))
    fade_soll_map.put( "Hinten_Oben",    new HSBType( "30,100,3"))

    Wohnzimmer_Fade_Zeit.sendCommand(3000)
end

rule "Bewegungsmelder Fade aus"
when
    Item Wohnzimmer_Fade_Bewegung_Tag    received update OFF or
    Item Wohnzimmer_Fade_Bewegung_Nacht    received update OFF
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    fade_soll_map.put( "Wait",    true as Boolean)
    
    fade_soll_map.put( "Vorne_Oben",    new HSBType( "0,0,0"))
    fade_soll_map.put( "Rechts_Oben",    new HSBType( "0,0,0"))
    fade_soll_map.put( "Hinten_Oben",    new HSBType( "0,0,0"))

    Wohnzimmer_Fade_Zeit.sendCommand(2000)
end

rule "Bewegungsmelder Wohnzimmer_Fade_Schalter"
when
    Item Wohnzimmer_Fade_Schalter    received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)
    
    val state = Wohnzimmer_Fade_Schalter.state

    if( state == OFF) {
        fade_soll_map.put( "Wait",    true as Boolean)
        fade_soll_map.put( "Vorne_Oben",    new HSBType( "0,0,0"))
        fade_soll_map.put( "Rechts_Oben",    new HSBType( "0,0,0"))
        fade_soll_map.put( "Hinten_Oben",    new HSBType( "0,0,0"))
        fade_soll_map.put( "Vorne_Unten",    new HSBType( "0,0,0"))
        fade_soll_map.put( "Rechts_Unten",    new HSBType( "0,0,0"))
        fade_soll_map.put( "Hinten_Unten",    new HSBType( "0,0,0"))
    }
    else {
        fade_soll_map.put( "Vorne_Oben",    new HSBType( "0,0,100"))
        fade_soll_map.put( "Rechts_Oben",    new HSBType( "0,0,100"))
        fade_soll_map.put( "Hinten_Oben",    new HSBType( "0,0,100"))
        fade_soll_map.put( "Vorne_Unten",    new HSBType( "0,0,100"))
        fade_soll_map.put( "Rechts_Unten",    new HSBType( "0,0,100"))
        fade_soll_map.put( "Hinten_Unten",    new HSBType( "0,0,100"))
    }

    Wohnzimmer_Fade_Zeit.sendCommand(2000)
end




rule "Fade Bewegungsmelder Waschmaschine"
when
    Item Wohnzimmer_Fade_Waschmaschine received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val state = Wohnzimmer_Fade_Waschmaschine.state

    var HSBType next = null
    if( state == ON)    next = new HSBType( "130,100,100")
    else                 next = new HSBType( "130,100,0")

    fade_soll_map.put( "Vorne_Unten",    next)
    fade_soll_map.put( "Rechts_Unten",    next)
    fade_soll_map.put( "Hinten_Unten",    next)
    
    if( state == OFF)    fade_soll_map.put( "Wait",    true as Boolean)
    
    Wohnzimmer_Fade_Zeit.sendCommand(3000)
end

rule "Fade Wohnzimmer_Fade_Schlafzimmerfenster"
when
    Item Wohnzimmer_Fade_Schlafzimmerfenster received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val state = Wohnzimmer_Fade_Schlafzimmerfenster.state

    var HSBType next = null
    if( state == ON)    next = new HSBType( "230,90,100")
    else                 next = new HSBType( "230,90,0")
    
    fade_soll_map.put( "Vorne_Unten", next)
    
    if( state == OFF) {
        fade_soll_map.put( "Wait",    true as Boolean)    
    }

    Wohnzimmer_Fade_Zeit.sendCommand(1000)

end



rule "Fade Wohnzimmer_Fade_Muell"
when
    Item Wohnzimmer_Fade_Muell received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val state = Wohnzimmer_Fade_Muell.state
    
    var HSBType next = null
    if( state == ON)    next = new HSBType( "307,83,100")
    else                 next = new HSBType( "307,83,0")
    
    fade_soll_map.put( "Vorne_Unten",    next)
    fade_soll_map.put( "Rechts_Unten",    next)
    fade_soll_map.put( "Hinten_Unten",    next)

    if( state == OFF)fade_soll_map.put( "Wait",    true as Boolean)


    Wohnzimmer_Fade_Zeit.sendCommand(3000)
    
    if( state == ON){
        createTimer(now.plusSeconds(90)) [|
            Wohnzimmer_Fade_Muell.postUpdate(OFF)
        ]
    }
end


rule "Fade Wohnzimmer_FADE_Luigi_online"
when
    Item Wohnzimmer_FADE_Luigi_online received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val state = Wohnzimmer_FADE_Luigi_online.state

    var HSBType next = null
    if( state == ON)    next = new HSBType( "131,88,100")
    else                 next = new HSBType( "131,88,0")
    
    if( state == OFF)    fade_soll_map.put( "Wait",    true as Boolean)
    fade_soll_map.put( "Hinten_Unten",    next)

    Wohnzimmer_Fade_Zeit.sendCommand(3000)
end



rule "Fade Wohnzimmer_FADE_Luigi_offline"
when
    Item Wohnzimmer_FADE_Luigi_offline received update
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val state = Wohnzimmer_FADE_Luigi_offline.state
    
    var HSBType next = null
    if( state == ON)    next = new HSBType( "17,87,100") 
    else                 next = new HSBType( "17,87,0")

    if( state == OFF)    fade_soll_map.put( "Wait",    true as Boolean)
    fade_soll_map.put( "Hinten_Unten",    next)

    Wohnzimmer_Fade_Zeit.sendCommand(2000)
end


rule "Fade Wohnzimmer_Fade_Alle_Aus"
when
    Item Wohnzimmer_Fade_Alle_Aus received update ON
then
    var boolean wait = true
    do{
        to_copy_lock.lock()
        wait = to_copy_state
        if( !to_copy_state) to_copy_state = true
        to_copy_lock.unlock()
        
        if( wait) Thread::sleep(100)
    }
    while(wait)

    val HSBType VO = Wohnzimmer_Vorne_Oben.state as HSBType
    val HSBType RO = Wohnzimmer_Rechts_Oben.state as HSBType
    val HSBType HO = Wohnzimmer_Hinten_Oben.state as HSBType
    val HSBType VU = Wohnzimmer_Vorne_Unten.state as HSBType
    val HSBType RU = Wohnzimmer_Rechts_Unten.state as HSBType
    val HSBType HU = Wohnzimmer_Hinten_Unten.state as HSBType
    
    //Aus wartet immer
    fade_soll_map.put( "Wait",    true as Boolean)
    
    if( VO.brightness > 0)    fade_soll_map.put( "Vorne_Oben",    new HSBType(VO.hue, VO.saturation, new PercentType(0)))
    if( RO.brightness > 0)    fade_soll_map.put( "Rechts_Oben",    new HSBType(RO.hue, RO.saturation, new PercentType(0)))
    if( HO.brightness > 0)    fade_soll_map.put( "Hinten_Oben",    new HSBType(HO.hue, HO.saturation, new PercentType(0)))
    if( VU.brightness > 0)    fade_soll_map.put( "Vorne_Unten",    new HSBType(HO.hue, HO.saturation, new PercentType(0)))
    if( RU.brightness > 0)    fade_soll_map.put( "Rechts_Unten",    new HSBType(RU.hue, RU.saturation, new PercentType(0)))
    if( HU.brightness > 0)    fade_soll_map.put( "Hinten_Unten",    new HSBType(HU.hue, HU.saturation, new PercentType(0)))


    Wohnzimmer_Fade_Zeit.sendCommand(2000)
end



rule "test"
when
    Item test changed or
    System started
then
    val tsstart = DateTimeUtils::currentTimeMillis()
    
    var HashMap<String, String> map_soll =    newLinkedHashMap( "" -> "") as LinkedHashMap<String, String>
    
    var i = 0
    
    do {
        map_soll.put( String::format("%d", i), String::format("%d", i))
        i = i + 1
    }
    while( i < 100000)

    logInfo(    "Wohnzimmer", String::format( "Dauer %dms", DateTimeUtils::currentTimeMillis() - tsstart))
end






//-----------------------------------------------------------------------------------------------------------------------------------------------------------
// Fade Wohnzimmer init
//-----------------------------------------------------------------------------------------------------------------------------------------------------------

rule "Fade Wohnzimmer init"
when
    Item Initialize received update ON or
    System started
then
    Wohnzimmer_Vorne_Oben.sendCommand( "0,0,0")
    Wohnzimmer_Rechts_Oben.sendCommand( "0,0,0")
    Wohnzimmer_Hinten_Oben.sendCommand( "0,0,0")

    Wohnzimmer_Vorne_Unten.sendCommand( "0,0,0")
    Wohnzimmer_Rechts_Unten.sendCommand( "0,0,0")
    Wohnzimmer_Hinten_Unten.sendCommand( "0,0,0")
    
    Wohnzimmer_Fade_Zeit.postUpdate(0)
    
    fades_lock.lock()
    fades_anz = 0
    fades_lock.unlock()
    
    to_copy_lock.lock()
    to_copy_state    = false
    to_copy_lock.unlock()
end


//-----------------------------------------------------------------------------------------------------------------------------------------------------------
// Execute Fade
//-----------------------------------------------------------------------------------------------------------------------------------------------------------
rule "Execute Fade"
when
    Item Wohnzimmer_Fade_Zeit received update
then
    var Integer steps = (Wohnzimmer_Fade_Zeit.state as DecimalType / 50).intValue()
    if( steps <= 0) {
        to_copy_lock.lock()
        to_copy_state = false
        to_copy_lock.unlock()
        return false    
    }
    logDebug( "Wohnzimmer", String::format( "%15s | 1", "Fade"))
    val keys = newArrayList("Vorne_Oben", "Rechts_Oben", "Hinten_Oben", "Vorne_Unten", "Rechts_Unten", "Hinten_Unten")

    var long start = DateTimeUtils::currentTimeMillis()

    var HashMap<String, Object> map_soll =    newLinkedHashMap( "" -> null as Object) as LinkedHashMap<String, Object>

    //Copy locally
    for( key : keys) {
        map_soll.put( key, fade_soll_map.get(key))
        fade_soll_map.put( key, null)
    }
    map_soll.put( "Wait", fade_soll_map.get("Wait"))
    fade_soll_map.put( "Wait", false as Boolean)

    //Available for copiing again
    to_copy_lock.lock()
    to_copy_state = false
    to_copy_lock.unlock()
    


    //Bei Wait warten, bis alle Fades fertig sind
    val boolean wait = if( map_soll.get("Wait") as Boolean) true else false
    
    if( wait) {
        var int tmp = 1
        while (tmp > 0) {
            fades_lock.lock()
            tmp = fades_anz
            fades_lock.unlock()
            
            if( tmp > 0) Thread::sleep(250)
        }
    }


    //Anzahl erhöhen
    fades_lock.lock()
    fades_anz = fades_anz + 1
    val fade_id = fades_anz
    fades_lock.unlock()



    if( wait) {
        logDebug( "Wohnzimmer", String::format( "%15s | Wait complete %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - start))
        start = DateTimeUtils::currentTimeMillis()
    }

    logDebug( "Wohnzimmer", String::format( "%15s | Start %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - start))


    
    
    
    //initialisieren
    var HashMap<String, LinkedHashMap<String, Object>> fade_data = newLinkedHashMap(
        "Vorne_Oben" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Vorne_Oben as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>,
        "Rechts_Oben" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Rechts_Oben as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>,
        "Hinten_Oben" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Hinten_Oben as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>,
        "Vorne_Unten" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Vorne_Unten as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>,
        "Rechts_Unten" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Rechts_Unten as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>,
        "Hinten_Unten" -> newLinkedHashMap(
            "Do"    -> false as Boolean,
            "Item"    -> Wohnzimmer_Hinten_Unten as Object,
            "Dummy"    -> null as Object
        ) as LinkedHashMap<String, Object>
    )
    
    
    var boolean do_sth = false

    for( key : keys) {
        var Object soll_obj    = (map_soll.get( key)) as Object
        
        if( soll_obj != null) {
            var soll = soll_obj as HSBType
            var data = fade_data.get( key)
            
            var item = (data.get("Item")) as org.openhab.core.items.GenericItem
            var ist     = item.state as HSBType
            
            data.put( "Do",        true as Boolean)
            data.put( "Soll",    soll as HSBType)
            
            var float diff_H    = (soll.hue - ist.hue).floatValue()                    / steps
            var float diff_S    = (soll.saturation - ist.saturation).floatValue()    / steps;
            var float diff_B    = (soll.brightness - ist.brightness).floatValue()    / steps            

            //If we start from 0 brightness set color corectly!
            if( ist.brightness == 0) {
                diff_H    = 0.floatValue()
                diff_S    = 0.floatValue()
                item.sendCommand( new HSBType( soll.hue, soll.saturation, ist.brightness))
            }
            
            if( diff_H != 0 || diff_S != 0 || diff_B != 0) do_sth = true

            data.put( "Step Hue",            diff_H)
            data.put( "Step Saturation",    diff_S)
            data.put( "Step Brightness",    diff_B)
            
            logDebug( "Wohnzimmer", String::format( "%15s | %13s Step Hue:        %3.1f", "Fade" + fade_id.toString(), key, diff_H))
            logDebug( "Wohnzimmer", String::format( "%15s | %13s Step Saturation: %3.1f", "Fade" + fade_id.toString(), key, diff_S))
            logDebug( "Wohnzimmer", String::format( "%15s | %13s Step Brightness: %3.1f", "Fade" + fade_id.toString(), key, diff_B))
            
            //Fade History
            postUpdate(    item.name + "_0", item.state.toString())
        }
    }

    if( !do_sth){
        fades_lock.lock()
        fades_anz = fades_anz - 1
        fades_lock.unlock()
        return false
    }

    logDebug( "Wohnzimmer", String::format( "%15s | initialized: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - start))

    var long step_duration_ts = DateTimeUtils::currentTimeMillis()
    var int step_sleep    = 0

    //Fade Execution
    while (steps > 0) {
        step_duration_ts = DateTimeUtils::currentTimeMillis()
        
        for( key : keys) {
            
            var data = fade_data.get( key)
            
            if( data.get("Do") as Boolean) {
            
                var item             = (data.get("Item")) as org.openhab.core.items.GenericItem
                var HSBType ist        = item.state as HSBType
                
                var double    new_H    = ist.hue.floatValue() + (data.get("Step Hue") as Float)
                var double    new_S    = ist.saturation.floatValue() + (data.get("Step Saturation")    as Float)
                var double    new_B    = ist.brightness.floatValue() + (data.get("Step Brightness")    as Float)
            
                //Boundry-Check!!!
                if( new_H > 360.0) new_H = 360.0
                if( new_S > 100.0) new_S = 100.0
                if( new_B > 100.0) new_B = 100.0
                
                if( new_H < 0.0) new_H = 0.0
                if( new_S < 0.0) new_S = 0.0
                if( new_B < 0.0) new_B = 0.0

                val String str_H = String::format("%.3f", new_H).replace(",", ".")
                val String str_S = String::format("%.3f", new_S).replace(",", ".")
                val String str_B = String::format("%.3f", new_B).replace(",", ".")
                
                //logDebug( "Wohnzimmer", "Command: " + str_H + "," + str_S + "," + str_B)
                item.sendCommand( str_H + "," + str_S + "," + str_B)
            }
        }

        step_sleep = 50 - (DateTimeUtils::currentTimeMillis() - step_duration_ts).intValue
        if( step_sleep > 0) Thread::sleep( step_sleep)

        //logDebug( "Wohnzimmer", String::format( "%15s | sleep: %dms", "Fade" + fade_id.toString(), step_sleep))

        steps = steps - 1
    }


    //Anzahl verringern
    fades_lock.lock()
    fades_anz = fades_anz - 1
    fades_lock.unlock()

    logDebug( "Wohnzimmer", String::format( "%15s | finished: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - start))
end




I’ve only had time to quickly scan the code but the general pattern seems to be when an event occurs update the fade_soll_map with the desired end states of the lights and fire off a new rule that applies the fade. And it looks like the bulk of the work is done in the last rule so that is where I focused.

And I will trust you when you say that the cause of the delay is in pulling data out of the Hashmap and not being caused by waiting for locks or waiting for events to propagate from one rule to the next.

Have you put in log statements and such to help pinpoint exactly where in your rules the delay is occurring or just observed that it is taking 120-750 msec for your fade rule to execute? Because the logic is so long and complicated seeing exactly where you are seeing the slowdown can narrow the focus.

Again, after only a quick scan a couple of things stand out to me.

In the middle of your fade you initialize a nested Hashmap of Hashmaps. While this is something perfectly natural to do in a language like Python, Perl, or JavaScript which has some major optimizations built around Hashmaps, I’m not surprised the Rules DSL is having difficulty with it and I suspect the underlying algorithm to generate the Hash and/or the initial size of the Hashmap is such that you don’t get good performance for small maps.

Have you tried to use just plain old HashMap instead of LinkedHashMap? I have no idea about the differences in performance of the two but it would be trivial to try.

I do not see anything in how you use fade_data nor any of the other Maps that seems to require using Hashmaps for these data structures at all except for your convenience (i.e. you can pull values out by name rather than index). I’d be willing to bet that if you even just switched to making fade_data a HashMap of ArrayLists, or even better an ArrayList of ArrayLists you would see a significant speedup in the Rules DSL performance. You are just iterating over the keys anyway so you should be able to just as easily use indices (create an Enum if you really want to keep using the name) instead and then you are looking at O(1) performance to get the data out instead of what ever degenerate edge case you seem to be hitting by using the Hashmaps which are clearly not giving you O(1) like the ideal Hashmap should.

Also, have you measured how long it takes to initialize those Rule local Hashmaps? As a general rule in Java (ultimately it is the Java underneath all of this stuff the most expensive thing you can do is the creation and destruction of objects. So the first thing a good Java programmer will do to address performance will be to find ways to reuse objects (e.g. use StringBuilder which lets you add new text to the same object rather than using String append (i.e. +) which results in the creation and destruction of three objects for every append, using object pools and repopulating their values rather than creating a new object, etc). Figuring out how to move the creation of fade_data and the other rule local Hashmaps out of the rule and into a Global could help, assuming that you are measuring a slowdown here. Of course, it is only occurring once per rule execution so I’m guessing that is not a problem.

Is there an opportunity to multi-thread the fade code? For example, move the bodies of some of your loops (start with the last one) into a Timer that is schedule to start in 1 msec and create a Timer for each key or step. I’ve not looked into it but you also might be able to use some of the Java native Thread stuff to do this as well (which would be nice as you can do a kind of fork at the front and a join at the end of the for loops. Even on a single processor computer often times this can make your code run faster, particularly if there is some IO involved and the RaspPi 2 has four cores so you are bound to see improvement (assuming the code in the loops run long enough to justify the cost of the extra overhead of creating the threads). This also could be a good technique to get all the lights to trigger closer together rather than in sequence.

Some other minor things which are probably not problems given you have already identified the Maps as being a problem:

  • Like I said before String appending using “+” is expensive and so is the replace method (in Java Strings are immutable to to perform the replace requires the creation and destruction of objects for each match) so the last part of your execute fade loop could add up to a good deal of delay. It is probably not your problem but it something to be aware of when looking for how to optimize code. A StringBuilder would save you here.
  • It is probably more efficient to round your values using Math::round() than it is to use String::format()

Finally, if you want/need your Hashmap to be thread safe use ConcurrentHashMap instead of LinkedHashMap, though keep in mind that using a synchronized data structure is going to be slower than the non-synchronized data structure.

1 Like

I think we can agree to check for the worker-loop.
Below is the code which I used to check for a delay.
As you can see for each of the keys (6) I outline the time.

        for( key : keys) {
            
            measure = DateTimeUtils::currentTimeMillis()
            var data = fade_data.get( key)
            
            if( data.get("Do") as Boolean) {
                
            
                var item             = (data.get("Item")) as org.openhab.core.items.GenericItem
                var HSBType ist        = item.state as HSBType
                
                var double    new_H    = ist.hue.floatValue() + (data.get("Step Hue") as Float)
                var double    new_S    = ist.saturation.floatValue() + (data.get("Step Saturation")    as Float)
                var double    new_B    = ist.brightness.floatValue() + (data.get("Step Brightness")    as Float)

                logDebug( "Wohnzimmer", String::format( "%15s | Get: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - measure))
            
                //Boundry-Check!!!
                if( new_H > 360.0) new_H = 360.0
                if( new_S > 100.0) new_S = 100.0
                if( new_B > 100.0) new_B = 100.0
                
                if( new_H < 0.0) new_H = 0.0
                if( new_S < 0.0) new_S = 0.0
                if( new_B < 0.0) new_B = 0.0

                logDebug( "Wohnzimmer", String::format( "%15s | Check: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - measure))

                val String str_H = String::format("%.3f", new_H).replace(",", ".")
                val String str_S = String::format("%.3f", new_S).replace(",", ".")
                val String str_B = String::format("%.3f", new_B).replace(",", ".")
                
                logDebug( "Wohnzimmer", String::format( "%15s | String: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - measure))
                //logDebug( "Wohnzimmer", "Command: " + str_H + "," + str_S + "," + str_B)
                item.sendCommand( str_H + "," + str_S + "," + str_B)
                logDebug( "Wohnzimmer", String::format( "%15s | Send: %dms", "Fade" + fade_id.toString(), DateTimeUtils::currentTimeMillis() - measure))
            }
        }

2016-03-19 08:42:37.730 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Get: 23ms
2016-03-19 08:42:37.743 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Check: 35ms
2016-03-19 08:42:37.757 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | String: 49ms
2016-03-19 08:42:37.791 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Send: 83ms
2016-03-19 08:42:37.843 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Get: 20ms
2016-03-19 08:42:38.166 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Check: 342ms
2016-03-19 08:42:38.180 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | String: 356ms
2016-03-19 08:42:38.209 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Send: 385ms
2016-03-19 08:42:38.235 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Get: 19ms
2016-03-19 08:42:38.248 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Check: 31ms
2016-03-19 08:42:38.261 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | String: 45ms
2016-03-19 08:42:38.286 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Send: 70ms
2016-03-19 08:42:38.312 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Get: 19ms
2016-03-19 08:42:38.325 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Check: 32ms
2016-03-19 08:42:38.339 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | String: 45ms
2016-03-19 08:42:38.368 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Send: 75ms

It takes aproximately 60ms per key which is 360ms for all the keys. My target time was 50ms for alle keys.

1 Like

OK, so Get is taking ~20 msec, Check is taking between ~15 and ~320 msec, send is taking ~15 msec.

Here is what I would recommend changing to tighten up this loop (in order):

  • First, I don’t trust the performance of String::format. The first things I would do is calculate your running time and store them in vals and only have one log statement at the end of the for loop. This will tell you how long it is taking your actual code to execute without being influenced by String operations and logging. Even better would be to eliminate the logging from the loop entirely. We are needing to shave tens of msec from the loop’s runtime and file IO (i.e. logging) is really slow. It does not good to optimize all of your calculations if the thing taking the most time is your logging and String manipulation to support the logging.

  • Consider using ints instead of doubles and floats for your new_H, new_S, etc. values. In general but particularly on ARM processors integer arrhythmic is more efficient than floating point and it is not clear to me you need the decimal precision for what you are doing (i.e. will you really be able to see the difference between 55.0 and 55.5? Does HSB even preserve the decimal place or just use it as int internally anyway?) This should speed up your Check code significantly and drastically speed up your String code (no more need to String::format or replace), though again I believe the log statement is actually dominating the running time.

  • Switch to using a single StringBuilder to construct all of your Strings within this loop. Outside the loop create a new val StringBuilder sb = new StringBuilder, construct your log statements using sb.append("Fade") sb.append(fade_id) sb.append(" | Get: ") .... The key is to avoid using String::format and avoid using String + operator. Particularly when we are looking to shave tens of msec off the runtime avoiding String and Date operations can be a killer. When it comes time to create a new log statement or build another String use sb.clear. These are just log statements and you are trying to shave msec off the runtime so for now lets not worry about truncating/rounding the floats in your logs. In my nearly 20 years of experience with Java and JVM languages this is the first thing I’ve learned to do when optimizing. This will also lessen the number of objects that get created significantly and therefore reduce how often the JVM will need to perform garbage collection.

  • I don’t know much about DateTimeUtils. You can try using System::currentTimeMillis instead in case DateTimeUtils does a bunch of extra work you don’t care about. One of the challenges of figuring these sorts of performance issues out is that you can’t measure it without impacting the performance so you have to be very careful not to add too much of your measuring (calculating timestamps, logging values, etc.) to the code being measured because pretty soon your measuring code starts to dominate the runtime. In fact, what I would probably do here is create a val for each segment of code and just grab currentTimeMillisec after each chunk of code and do the calculations and logging at the end. This will give you the measurements of one time through the loop as it will perform once you remove the measurement code, which is what you are really trying to get.

  • Switch to using ArrayLists instead of Hashmaps. With an ArrayList you will be guaranteed O(1) performance. I’m not convinced right now that the problem is indeed the Hashmap (I’m pretty sure its the String::format until I’m proven otherwise)

  • Assuming you didn’t switch to ints as suggested above, use Math::round to truncate your floats, and build your HSB String that you send to your item.

I really think the root of your problem is not the part of this code that actually does the work. I think it is the String manipulation and the logging. I’ll bet that if you changed how you are doing that and/or eliminate it you will get under your 50 msec goal.

1 Like

I tried to get rid of the String::format as you suggested.
It definitely made a huge performance impact (over 100ms per calculation):

    while (steps > 0) {
        step_duration_ts = DateTimeUtils::currentTimeMillis()
        
        for( key : keys) {
                        var data = fade_data.get( key)
            
            if( data.get("Do") as Boolean) {
                
            
                var item             = (data.get("Item")) as org.openhab.core.items.GenericItem
                var HSBType ist        = item.state as HSBType
                
                var double    new_H    = ist.hue.floatValue() + (data.get("Step Hue") as Float)
                var double    new_S    = ist.saturation.floatValue() + (data.get("Step Saturation")    as Float)
                var double    new_B    = ist.brightness.floatValue() + (data.get("Step Brightness")    as Float)
            
                //Boundry-Check!!!
                if( new_H > 360.0) new_H = 360.0
                if( new_S > 100.0) new_S = 100.0
                if( new_B > 100.0) new_B = 100.0
                
                if( new_H < 0.0) new_H = 0.0
                if( new_S < 0.0) new_S = 0.0
                if( new_B < 0.0) new_B = 0.0

                val String str_H = String::valueOf(new_H)
                val String str_S = String::valueOf(new_S)
                val String str_B = String::valueOf(new_B)

                item.sendCommand( str_H + "," + str_S + "," + str_B)
            }
        }

        step_end = DateTimeUtils::currentTimeMillis() - step_duration_ts
        logDebug( "Wohnzimmer", String::format( "%15s | Duration: %dms", "Fade" + fade_id.toString(), step_end))

        step_sleep = 50 - (DateTimeUtils::currentTimeMillis() - step_duration_ts).intValue
        if( step_sleep > 0) Thread::sleep( step_sleep)

        //logDebug( "Wohnzimmer", String::format( "%15s | sleep: %dms", "Fade" + fade_id.toString(), step_sleep))

        steps = steps - 1
    }

So I then modified the time measurement for all keys and it looks better:

2016-03-19 19:43:18.815 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 296ms
2016-03-19 19:43:19.133 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 296ms
2016-03-19 19:43:19.462 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 308ms
2016-03-19 19:43:19.779 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 295ms
2016-03-19 19:43:20.101 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 300ms
2016-03-19 19:43:20.417 [DEBUG] [penhab.model.script.Wohnzimmer] -           Fade1 | Duration: 296ms

I can’t go for ints because this is the fraction which it is increased each step. I want it smooth so I have to take floating point values.
The need for the string builder is obsolete with the new approach.
I am not sure I can go for an array since I am not really sure which items are affected. I would have to keep the items etc in a kind of struct (or even better a class - then I would immediately go for an array).

A linked hashmap preserves the order the items have been added. That’s the difference to a hashmap.
I found the following nice diagram on stackoverflow:

╔══════════════╦═════════════════════╦═══════════════════╦══════════════════════╗
║   Property   ║       HashMap       ║      TreeMap      ║     LinkedHashMap    ║
╠══════════════╬═════════════════════╬═══════════════════╬══════════════════════╣
║              ║  no guarantee order ║ sorted according  ║                      ║
║   Order      ║ will remain constant║ to the natural    ║    insertion-order   ║
║              ║      over time      ║    ordering       ║                      ║
╠══════════════╬═════════════════════╬═══════════════════╬══════════════════════╣
║  Get/put     ║                     ║                   ║                      ║
║   remove     ║         O(1)        ║      O(log(n))    ║         O(1)         ║
║ containsKey  ║                     ║                   ║                      ║
╠══════════════╬═════════════════════╬═══════════════════╬══════════════════════╣
║              ║                     ║   NavigableMap    ║                      ║
║  Interfaces  ║         Map         ║       Map         ║         Map          ║
║              ║                     ║    SortedMap      ║                      ║
╠══════════════╬═════════════════════╬═══════════════════╬══════════════════════╣
║              ║                     ║                   ║                      ║
║     Null     ║       allowed       ║    only values    ║       allowed        ║
║ values/keys  ║                     ║                   ║                      ║
╠══════════════╬═════════════════════╩═══════════════════╩══════════════════════╣
║              ║   Fail-fast behavior of an iterator cannot be guaranteed       ║
║   Fail-fast  ║ impossible to make any hard guarantees in the presence of      ║
║   behavior   ║           unsynchronized concurrent modification               ║
╠══════════════╬═════════════════════╦═══════════════════╦══════════════════════╣
║              ║                     ║                   ║                      ║
║Implementation║      buckets        ║   Red-Black Tree  ║    double-linked     ║
║              ║                     ║                   ║       buckets        ║
╠══════════════╬═════════════════════╩═══════════════════╩══════════════════════╣
║      Is      ║                                                                ║
║ synchronized ║              implementation is not synchronized                ║
╚══════════════╩════════════════════════════════════════════════════════════════╝

So while your suggested changes made a huge impact,
I still have to speed the code up ~600%.
However, I did not get the System::currentTimeMillis to run.
Thank’s for you help anyway! :slight_smile:

Actually you can. A common optimization technique in scientific computing is to multiply your value by 10 or 100 or what ever it takes to preserve the number of decimal places into an interview or a long, do the calculation, then divide it back to a float/double at the last moment where it us needed. Huge speedups when working with lots of numbers and/or you need high precision (computers suck at floating point math)

The need for the string builder is obsolete with the new approach.

You should still see some speed up if you use a String builder at the end where you construct the command. But probably not huge speedups.

It us more work (a lot more in some cases) but you can build structs like things and class like things in arrays. It just requires a lot of manual book keeping on the programmers part (welcome to old school programming). And with lambdas being first class Objects you can even build something like a class. It will be ugly and a lot of work but you can do it. So it isn’t so much a question of whether an ArrayList can work as it is a question of whether its worth the extra effort to make it work.

And there are all sorts of ways you can handle the problem where you don’t know a priori which Items are to be processed by the rule.

Maybe System isn’t available to the Rules DSL or maybe currentTimeMillis moved out of System at some point.

Where does the 600% come from? Are you trying to get the Rules DSL implementation to be as fast as the jython or do you need 600% to be fast enough to meet your 50 msec timelines?

One thing I find odd is that your times from your previous post were in the 50-100 msec range yet your times here are in the 300 msec range. What accounts for the extra 250 msec? I’m starting to wonder if the work loop is the problem at all.

The real problem here may be that the Rule’s DSL is truly an interpreted language whereas Python, if I remember correctly, does just in time compilation similar to how Java does it. If that is the case then we might just be stuck and the xtend will never be fast enough.

Hey,

what I think might caused some confusion is that the times that I posted were for one of the six lighting elements. If you take a look at the logDebug statements it’ll be clear to you. So you have to take the measure time x6 to get the time for the whole loop (75 * 6 = 450ms). So with 300ms for the whole loop now it is definitely a huge improvement!

What I am trying to do is to get any implementation of my fade scheduler whatsoever in 50ms. I have not implemented in jython so I don’t know wether it’ll be faster. I did the tests described in the other thread to get a first feeling if it’s worth to put in all the effort.

While running it all on my personal computer it was fine performance wise, I wasn’t just performing as well on the Pi2. So I started looking and tried to eliminate some unnecessary delay based on your suggestions.
If I have time, I’ll try to implement the same thing in jython and see how it performs. I think I won’t go for the extra effort with the Arraylist or the int implementation. This is a hobby for me, I am doing this in the evening after work and after all it has to be fun, too! :wink:

Jython does indeed compile to java bytecode. This is something which definitely might explain some performance discrepancy.
If I make any progress I’ll definitely keep you posted!

Ah, that makes a lot more sense.

So how important is it to you that the lights be processed in order? My idea of using Timers to run each iteration of the loop in parallel might get you to your goal, or at least close to it.

NOTE: I’m just typing this in, there is almost certainly an error but the concept should be valid.

while (steps > 0) {
    for( key : keys) {
        createTimer(now.plusMillis(1), [| // should trigger the code in a separate thread almost immediately, if not you may need to make it 5 or 10
            var data = fade_data.get(key)
            ...
        ]
    }
}

...
step_sleep = // this needs to be long enough for the loops to finish. With the changes already made 55 or 60 might be a good number here actually

Theoretically what should happen above is that the calculation of the new values and sendCommand for each light set (i.e. key) should process in parallel so it should only take slightly longer than it takes for the longest time through the loop for ALL the lights to finish processing. And depending on timing you may not have to wait until all the timers complete before moving to the next step as the old Timers will probably have completed before you get to sending the command on the next time through the loop.

One major drawback to this is that you are not always guaranteed that the lights are sent a command in the same order for each step. Also, if for some reason one of the threads has a hickup (e.g. garbage collection) a couple steps could process out of order. Because we are not using locks or anything like that (which we could use if we have to simulate a fork/join type behavior) you will have to come up with how long you have to sleep at the end of the while loop to ensure reliable behavior. But with an average of 50 msec per key you might be able to get away with a timeout of 50 msec with the code as is.

I’d give it a try and see what happens. It is simple enough to test out. And this could get you to your goal, or at least really close to it.

If it does work, you can then think about ways to make it more reliable/robust, though anything you add to it at this point will make it take longer. Things you can do include adding a lock for each Timer and and requiring all of the locks to be released before the next iteration of the for loop (fork/join), holding on to your Timer objects in case you need to cancel or reschedule them, etc.

1 Like

I did an implementation in jython.
Here is the worker-code.

    while( steps > 0):
        start_step = time.time()
        steps = steps - 1

        for key in fade:
            start_step1 = time.time()
            ist = HSBType( str(fade_items[key].state))
            h = float(str(ist.hue))           + fade[key]["step h"]
            s = float(str(ist.saturation))    + fade[key]["step s"]
            b = float(str(ist.brightness))    + fade[key]["step b"]
            logger.debug("{:15s} | duration1 ({:3.5f}ms)".format( "DoFade", (time.time() - start_step1) * 1000))

            h = max(h, 0.0)
            s = max(s, 0.0)
            b = max(b, 0.0)
            
            h = min(h, 100.0)
            s = min(s, 100.0)
            b = min(b, 100.0)
            
            logger.debug("{:15s} | duration2 ({:3.5f}ms)".format( "DoFade", (time.time() - start_step1) * 1000))
            BusEvent.sendCommand( fade_items[key],  "{:.4f},{:.4f},{:.4f}".format(h,s,b))
            logger.debug("{:15s} | duration3 ({:3.5f}ms)".format( "DoFade", (time.time() - start_step1) * 1000))
        
        logger.debug("{:15s} | duration ({:3.5f}ms)".format( "DoFade", (time.time() - start_step) * 1000))
        logger.debug("{:15s} | sleep ({:3.5f}ms)".format( "DoFade", (0.050 - (time.time() - start_step)) ))

        duration = 0.050 - (time.time() - start_step)
        if( duration > 0.0):
            time.sleep( duration)

Turns out the main part of the delay comes from posting a command to an item (difference between duration2 and duration3 ). The jython-code is neglectably fast.

2016-03-21 13:41:31.266 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (2.00009ms)
2016-03-21 13:41:31.269 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (5.00011ms)
2016-03-21 13:41:31.297 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (32.00006ms)
2016-03-21 13:41:31.301 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (0.99993ms)
2016-03-21 13:41:31.303 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (3.99995ms)
2016-03-21 13:41:31.327 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (27.99988ms)
2016-03-21 13:41:31.331 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (2.00009ms)
2016-03-21 13:41:31.334 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (3.99995ms)
2016-03-21 13:41:31.353 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (23.99993ms)
2016-03-21 13:41:31.357 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (2.00009ms)
2016-03-21 13:41:31.360 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (3.99995ms)
2016-03-21 13:41:31.379 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (23.00000ms)
2016-03-21 13:41:31.383 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (0.99993ms)
2016-03-21 13:41:31.386 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (3.99995ms)
2016-03-21 13:41:31.410 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (27.99988ms)
2016-03-21 13:41:31.414 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration1 (1.00017ms)
2016-03-21 13:41:31.416 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration2 (3.99995ms)
2016-03-21 13:41:31.444 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration3 (32.00006ms)
2016-03-21 13:41:31.447 [DEBUG] [penhab.model.jsr223.Wohnzimmer] - DoFade          | duration (182.00016ms)

However, it is still noticeable, that the jython implementation is running ~10 times faster (~4ms compared to ~40ms) while doing the same thing.
Unfortunately I did not reach my goal of 50ms per cycle. I have to think of some code to prevent unnecessary item-commands.
Performance wise I am happy nonetheless. I save ~5min lag time on first time rule loading and the load on the pi seems to be much less (response-time of other rules went down, but I did not measure that).

Maybe I’ll go for six parallel worker threads as you suggested. We’ll see! Thank you for you ideas and contribution! :thumbsup: